Project

General

Profile

subscribe2.txt

LogFrom10amApri19 - Anonymous, 04/19/2017 10:42 AM

Download (39.5 KB)

 
1
Updating local copy of the accessors repository.
2
In "/Users/cxh/ptII/org/terraswarm/accessor/accessors", about to execute:
3
    svn update --non-interactive --trust-server-cert --accept postpone
4
Updating '.':
5
At revision 1574.
6
All Done
7
Updated accessor repository.
8
GDPLogCreate.js: initialize()
9
GDPLogAppend.js: initialize()
10
GDPLogCreate.js: create() Start.
11
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733, 3, edu.berkeley.eecs.gdp-01.gdplogd): 
12
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
13
GDPManager: gdp settings:
14
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
15
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@571b0cf8, 3, org.terraswarm.gdp.GDP_NAME@72215aa7)
16
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@571b0cf8(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo), RA, org.terraswarm.gdp.GDP_NAME@72215aa7(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
17

    
18
>>> gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo)
19
_gdp_lib_init(NULL)
20
	@(#)libgdp 0.7.2 (2017-04-19 10:33) 0de5c9d3404f5aacdab3c4b9c196c30fd943a041
21
My GDP routing name = 6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
22
gdp_lib_init: OK
23
_gdp_chan_open(gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu)
24
Trying gdp-03.eecs.berkeley.edu
25
_gdp_chan_open: trying host gdp-03.eecs.berkeley.edu port 8007
26
_gdp_chan_open: talking to router at gdp-03.eecs.berkeley.edu:8007
27
gdp_event_loop: starting up I/O base loop
28
Inserted events:
29
  0x7fe78d6dbd10 [fd  126] Write Persist
30
  0x7fe78d6dbc90 [fd  126] Read Persist
31
  0x7fe78d743710 [fd  -1] Persist Timeout=1492623731.674795
32
Active events:
33
_gdp_req_new: allocated new pdu @ 0x7fe789109250
34
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_ADVERTISE
35
gdp_init: OK
36
_gdp_req_new: allocated new pdu @ 0x7fe789109250
37

    
38
>>> _gdp_invoke(req=0x7fe789131f60 rid=1): CMD_OPEN_RA (75), gcl@0x7fe7891321a0
39
	datum @ 0x7fe789132080: recno -1, len 0, no timestamp
40
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_OPEN_RA
41
_gdp_pdu_in(NAK_R_NOROUTE) => OK
42

    
43
*** Processing ack/nak 240=NAK_R_NOROUTE from socket 126
44
gdp_pdu_proc_resp(0x7fe78d3e8200 NAK_R_NOROUTE) gcl 0x7fe7891321a0
45
_gdp_req_dispatch >>> NAK_R_NOROUTE (240) [gcl->refcnt 2]
46
nak_router: received NAK_R_NOROUTE for CMD_OPEN_RA
47
_gdp_req_dispatch <<< NAK_R_NOROUTE [gcl->refcnt 2]
48
    ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
49
<<< _gdp_invoke(0x7fe789131f60 rid=1) CMD_OPEN_RA: ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
50
Couldn't open GCL uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo:
51
	ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
52
<<< gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo): ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
53
GDP_GCL: gdp_gcl_open() failed, trying to create the log and call gdp_gcl_open() again.
54
GDP_GCL.java: create(org.terraswarm.gdp.GDP_NAME@571b0cf8, , org.terraswarm.gdp.GDP_NAME@72215aa7, {})
55

    
56
>>> gdp_gcl_create
57
_gdp_gcl_create: gcl=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
58
	logd=m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
59
_gdp_req_new: allocated new pdu @ 0x7fe789109250
60

    
61
>>> _gdp_invoke(req=0x7fe789131f60 rid=2): CMD_CREATE (66), gcl@0x7fe78d4c2c30
62
	datum @ 0x7fe789132080: recno -1, len 34, no timestamp
63
00000000 b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea 5b 53 7d 43
64
         ?  ?  J  ?  ?  ?  ?  ?  ^  ?  :  ?  [  S  }  C 
65
00000010 d2 41 42 b2 85 67 10 bb b9 17 61 eb 3f 2f 61 6a
66
         ?  A  B  ?  ?  g  ?  ?  ?  ?  a  ?  ?  /  a  j 
67
00000020 00 00
68
         ?  ? 
69
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_CREATE
70
_gdp_pdu_in(ACK_DATA_CREATED) => OK
71

    
72
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 126
73
gdp_pdu_proc_resp(0x7fe78d3e8200 ACK_DATA_CREATED) gcl 0x7fe78d4c2c30
74
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 2]
75
ack_success: received ACK_DATA_CREATED for CMD_CREATE
76
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 2]
77
    OK [201 = 0xc9]
78
<<< _gdp_invoke(0x7fe789131f60 rid=2) CMD_CREATE: OK [201 = 0xc9]
79
<<< gdp_gcl_create: OK [201 = 0xc9]
80

    
81
>>> gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo)
82
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fe78d4c2c30
83
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
84

    
85
GDPLogCreate.js: create() Done!
86
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733, 1, edu.berkeley.eecs.gdp-01.gdplogd): 
87
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
88
GDPManager: gdp settings:
89
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
90
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@71f3abe2, 1, org.terraswarm.gdp.GDP_NAME@52e43229)
91
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@71f3abe2(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo), RO, org.terraswarm.gdp.GDP_NAME@52e43229(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
92

    
93
>>> gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo)
94
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fe78d4c2c30
95
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
96
_gdp_req_new: allocated new pdu @ 0x7fe789109250
97

    
98
>>> _gdp_invoke(req=0x7fe789131f60 rid=3): CMD_SUBSCRIBE (72), gcl@0x7fe78d4c2c30
99
	datum @ 0x7fe789132080: recno 0, len 4, no timestamp
100
00000000 00 00 00 00
101
         ?  ?  ?  ? 
102
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_SUBSCRIBE
103
_gdp_pdu_in(ACK_SUCCESS) => OK
104

    
105
*** Processing ack/nak 128=ACK_SUCCESS from socket 126
106
gdp_pdu_proc_resp(0x7fe78d3e8200 ACK_SUCCESS) gcl 0x7fe78d4c2c30
107
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 5]
108
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
109
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 5]
110
    OK [200 = 0xc8]
111
<<< _gdp_invoke(0x7fe789131f60 rid=3) CMD_SUBSCRIBE: OK [200 = 0xc8]
112
Starting subscription poker thread
113
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733
114
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733, 2, edu.berkeley.eecs.gdp-01.gdplogd): 
115
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
116
GDPManager: gdp settings:
117
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
118
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@31d41b60, 2, org.terraswarm.gdp.GDP_NAME@3d754b7e)
119
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@31d41b60(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo), AO, org.terraswarm.gdp.GDP_NAME@3d754b7e(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
120

    
121
>>> gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo)
122
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fe78d4c2c30
123
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
124
Append data: 1
125
GDPHelper.append(1)
126
ep_thr_mutex_lock    gdp_datum.c:64 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
127
ep_thr_mutex_unlock  gdp_datum.c:69 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
128
gdp_datum_new => 0x7fe789132080
129

    
130
>>> gdp_gcl_append
131
ep_thr_mutex_lock    gdp_api.c:465 0x7fe78d4c2c30 (gcl) [0x70000bd9c000]
132
ep_thr_mutex_lock    gdp_req.c:139 0x15b5a8070 (&ReqFreeListMutex) [0x70000bd9c000]
133
ep_thr_mutex_unlock  gdp_req.c:144 0x15b5a8070 (&ReqFreeListMutex) [0x70000bd9c000]
134
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
135
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
136
ep_thr_mutex_init    gdp_req.c:161 0x7fe78d65a8b0 (&req->mutex) [0x70000bd9c000]
137
ep_thr_cond_init     gdp_req.c:163 0x7fe78d65a900 (&req->cond) [0x70000bd9c000]
138
_gdp_req_lock: req @ 0x7fe78d65a8b0
139
ep_thr_mutex_lock    gdp_req.c:383 0x7fe78d65a8b0 (&req->mutex) [0x70000bd9c000]
140
ep_thr_mutex_lock    gdp_pdu.c:780 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
141
ep_thr_mutex_unlock  gdp_pdu.c:789 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
142
ep_thr_mutex_lock    gdp_datum.c:64 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
143
ep_thr_mutex_unlock  gdp_datum.c:69 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
144
gdp_datum_new => 0x7fe78d3d8cc0
145
_gdp_pdu_new => 0x7fe78d3e8200
146
_gdp_req_new: allocated new pdu @ 0x7fe78d3e8200
147
ep_thr_mutex_lock    gdp_req.c:195 0x7fe78d6dbbc0 (&chan->mutex) [0x70000bd9c000]
148
ep_thr_mutex_unlock  gdp_req.c:205 0x7fe78d6dbbc0 (&chan->mutex) [0x70000bd9c000]
149
_gdp_req_new(gcl=0x7fe78d4c2c30, cmd=CMD_APPEND) => 0x7fe78d65a8b0 (rid=0)
150

    
151
>>> _gdp_invoke(req=0x7fe78d65a8b0 rid=0): CMD_APPEND (71), gcl@0x7fe78d4c2c30
152
	datum @ 0x7fe78d3d8cc0: recno 1, len 1, no timestamp
153
00000000 31
154
         1 
155
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
156
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
157
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
158
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
159
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
160
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000bd9c000]
161
_gdp_invoke: sending 71, retries=2
162
_gdp_req_send: req@0x7fe78d65a8b0:
163
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
164
    postproc=0x0, sub_cb=0x0, udata=0x0
165
    state=ACTIVE, stat=OK
166
    act_ts=1970-01-01 00:00:00.000000000Z
167
    flags=0x100<ON_CHAN_LIST>
168
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
169
	iomode = 3, refcnt = 6, reqs = 0x7fe789131f60, nrecs = 1
170
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
171
    cPDU@0x7fe78d3e8200: 
172
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
173
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
174
	src=(none)
175
	rid=0, olen=0, chan=0x0, seqno=0
176
	flags=0
177
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=1
178
		ts=(none)
179
	sigmdalg=0x0, siglen=0, sig=0x0
180
	total header=88
181
_gdp_req_send(0x7fe78d65a8b0) gcl=0x7fe78d4c2c30
182
_gdp_req_send(0x7fe78d4c2c30) adding to cache
183
_gdp_gcl_cache_add(0x7fe78d4c2c30): adding
184
_gdp_gcl_cache_add(0x7fe78d4c2c30): already cached
185
_gdp_pdu_out, fd = 126, basemd = 0x0:
186
    PDU@0x7fe78d3e8200: 
187
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
188
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
189
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
190
	rid=0, olen=0, chan=0x0, seqno=0
191
	flags=0
192
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=1
193
		ts=(none)
194
	sigmdalg=0x0, siglen=0, sig=0x0
195
	total header=88
196
_gdp_pdu_out: sending PDU:
197
00000000 03 0f 00 47 b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea
198
00000010 5b 53 7d 43 d2 41 42 b2 85 67 10 bb b9 17 61 eb
199
00000020 3f 2f 61 6a e8 12 81 57 cd f2 4c 8d d9 2a 4f 79
200
00000030 8c a3 7a 73 ff 95 aa 4e a5 79 2a 66 37 80 a1 cd
201
00000040 4b c0 6a 1c 00 00 00 00 00 00 02 02 00 00 00 01
202
00000050 00 00 00 00 00 00 00 01
203
00000058                         31
204
                                 1 
205
_gdp_invoke: waiting on 0x7fe78d65a8b0
206
ep_thr_mutex_unlock  gdp_proto.c:143 0x7fe78d4c2c30 (req->gcl) [0x70000bd9c000]
207
ep_thr_cond_wait-cv  gdp_proto.c:146 0x7fe78d65a900 (&req->cond) [0x70000bd9c000]
208
ep_thr_cond-wait-mtx gdp_proto.c:146 0x7fe78d65a8b0 (&req->cond) [0x70000bd9c000]
209
gdp_read_cb: fd 126, 105 bytes
210
ep_thr_mutex_lock    gdp_pdu.c:780 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
211
ep_thr_mutex_unlock  gdp_pdu.c:789 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
212
ep_thr_mutex_lock    gdp_datum.c:64 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
213
ep_thr_mutex_unlock  gdp_datum.c:69 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
214
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000b553000]
215
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000b553000]
216
ep_thr_mutex_init    gdp_datum.c:75 0x7fe78d77da80 (&datum->mutex) [0x70000b553000]
217
gdp_datum_new => 0x7fe78d77da80
218
_gdp_pdu_new => 0x7fe78d5de430
219

    
220
	>>>>>  _gdp_pdu_in  >>>>>
221
_gdp_pdu_in: fixed pdu header:
222
00000000 03 0f 00 85 e8 12 81 57 cd f2 4c 8d d9 2a 4f 79
223
00000010 8c a3 7a 73 ff 95 aa 4e a5 79 2a 66 37 80 a1 cd
224
00000020 4b c0 6a 1c b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea
225
00000030 5b 53 7d 43 d2 41 42 b2 85 67 10 bb b9 17 61 eb
226
00000040 3f 2f 61 6a 00 00 00 03 00 00 06 0a 00 00 00 01
227
_gdp_pdu_in: read PDU header:
228
00000000 03 0f 00 85 e8 12 81 57 cd f2 4c 8d d9 2a 4f 79
229
00000010 8c a3 7a 73 ff 95 aa 4e a5 79 2a 66 37 80 a1 cd
230
00000020 4b c0 6a 1c b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea
231
00000030 5b 53 7d 43 d2 41 42 b2 85 67 10 bb b9 17 61 eb
232
00000040 3f 2f 61 6a 00 00 00 03 00 00 06 0a 00 00 00 01
233
00000050 00 00 00 00 00 00 00 01 00 00 00 00 58 f7 a1 55
234
00000060 3a 0a d3 60 00 00 00 00
235
_gdp_pdu_in: reading 1 data bytes (1 available)
236
00000068                         31
237
                                 1 
238
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
239
PDU@0x7fe78d5de430: 
240
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
241
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
242
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
243
	rid=3, olen=24, chan=0x7fe78d6dbbc0, seqno=0
244
	flags=0xa<HAS_RECNO,HAS_TS>
245
	datum=0x7fe78d77da80, recno=1, dbuf=0x7fe78d739c70, dlen=1
246
		ts=2017-04-19 17:41:41.973788000Z
247
	sigmdalg=0x0, siglen=0, sig=0x0
248
	total header=128
249

    
250
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 126
251
ep_thr_mutex_lock    ep_hash.c:169 0x7fe78e7f1630 (&hp->mutex) [0x70000b553000]
252
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe78e7f1630 (&hp->mutex) [0x70000b553000]
253
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fe78d4c2c30 (gcl) [0x70000b553000]
254
_gdp_gcl_touch(0x7fe78d4c2c30)
255
_gdp_gcl_incref(0x7fe78d4c2c30): 7
256
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
257
	0x7fe78d4c2c30 refcnt 7
258
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CONTENT) gcl 0x7fe78d4c2c30
259
gdp_pdu_proc_resp: searching gcl 0x7fe78d4c2c30 for rid 3
260
_gdp_req_find(gcl=0x7fe78d4c2c30, rid=3)
261
_gdp_req_lock: req @ 0x7fe78d65a8b0
262
ep_thr_mutex_lock    gdp_req.c:383 0x7fe78d65a8b0 (&req->mutex) [0x70000b553000]
263
_gdp_req_unlock: req @ 0x7fe78d65a8b0
264
ep_thr_mutex_unlock  gdp_req.c:404 0x7fe78d65a8b0 (&req->mutex) [0x70000b553000]
265
_gdp_req_lock: req @ 0x7fe789131f60
266
ep_thr_mutex_lock    gdp_req.c:383 0x7fe789131f60 (&req->mutex) [0x70000b553000]
267
_gdp_req_find(gcl=0x7fe78d4c2c30, rid=3) => 0x7fe789131f60, state IDLE
268
... found req@0x7fe789131f60:
269
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
270
    postproc=0x0, sub_cb=0x0, udata=0x0
271
    state=IDLE, stat=OK [200 = 0xc8]
272
    act_ts=2017-04-19 17:41:41.924856000Z
273
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
274
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
275
	iomode = 3, refcnt = 7, reqs = 0x7fe78d65a8b0, nrecs = 1
276
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
277
    cPDU@0x7fe789109250: 
278
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
279
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
280
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
281
	rid=3, olen=0, chan=0x0, seqno=0
282
	flags=0
283
	datum=0x0
284
	total header=80
285
ep_thr_mutex_unlock  gdp_main.c:410 0x7fe78d4c2c30 (gcl) [0x70000b553000]
286
gdp_pdu_proc_resp: req@0x7fe789131f60:
287
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
288
    postproc=0x0, sub_cb=0x0, udata=0x0
289
    state=IDLE, stat=OK [200 = 0xc8]
290
    act_ts=2017-04-19 17:41:41.924856000Z
291
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
292
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
293
	iomode = 3, refcnt = 7, reqs = 0x7fe78d65a8b0, nrecs = 1
294
	flags = 0xa<INCACHE,INUSE>
295
    cPDU@0x7fe789109250: 
296
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
297
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
298
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
299
	rid=3, olen=0, chan=0x0, seqno=0
300
	flags=0
301
	datum=0x0
302
	total header=80
303
    rPDU@0x7fe78d5de430: 
304
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
305
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
306
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
307
	rid=3, olen=24, chan=0x7fe78d6dbbc0, seqno=0
308
	flags=0xa<HAS_RECNO,HAS_TS>
309
	datum=0x7fe78d77da80, recno=1, dbuf=0x7fe78d739c70, dlen=1
310
		ts=2017-04-19 17:41:41.973788000Z
311
	sigmdalg=0x0, siglen=0, sig=0x0
312
	total header=128
313
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 7], req@0x7fe789131f60:
314
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
315
    postproc=0x0, sub_cb=0x0, udata=0x0
316
    state=IDLE, stat=OK [200 = 0xc8]
317
    act_ts=2017-04-19 17:41:41.995717000Z
318
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
319
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
320
	iomode = 3, refcnt = 7, reqs = 0x7fe78d65a8b0, nrecs = 1
321
	flags = 0xa<INCACHE,INUSE>
322
    cPDU@0x7fe789109250: 
323
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
324
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
325
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
326
	rid=3, olen=0, chan=0x0, seqno=0
327
	flags=0
328
	datum=0x0
329
	total header=80
330
    rPDU@0x7fe78d5de430: 
331
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
332
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
333
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
334
	rid=3, olen=24, chan=0x7fe78d6dbbc0, seqno=0
335
	flags=0xa<HAS_RECNO,HAS_TS>
336
	datum=0x7fe78d77da80, recno=1, dbuf=0x7fe78d739c70, dlen=1
337
		ts=2017-04-19 17:41:41.973788000Z
338
	sigmdalg=0x0, siglen=0, sig=0x0
339
	total header=128
340

    
341
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
342
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 7]
343
    OK [205 = 0xcd]
344
    req@0x7fe789131f60:
345
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
346
    postproc=0x0, sub_cb=0x0, udata=0x0
347
    state=IDLE, stat=OK [200 = 0xc8]
348
    act_ts=2017-04-19 17:41:41.995884000Z
349
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
350
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
351
	iomode = 3, refcnt = 7, reqs = 0x7fe78d65a8b0, nrecs = 1
352
	flags = 0xa<INCACHE,INUSE>
353
    cPDU@0x7fe789109250: 
354
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
355
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
356
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
357
	rid=3, olen=0, chan=0x0, seqno=0
358
	flags=0
359
	datum=0x0
360
	total header=80
361
    rPDU@0x7fe78d5de430: 
362
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
363
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
364
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
365
	rid=3, olen=24, chan=0x7fe78d6dbbc0, seqno=0
366
	flags=0xa<HAS_RECNO,HAS_TS>
367
	datum=0x7fe78d77da80, recno=1, dbuf=0x7fe78d739c70, dlen=1
368
		ts=2017-04-19 17:41:41.973788000Z
369
	sigmdalg=0x0, siglen=0, sig=0x0
370
	total header=128
371
acknak_from_estat: OK [205 = 0xcd] -> ACK_DATA_CONTENT
372
gdp_pdu_proc_resp(ACK_DATA_CONTENT for CMD_SUBSCRIBE): OK [205 = 0xcd]
373
req@0x7fe789131f60:
374
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
375
    postproc=0x0, sub_cb=0x0, udata=0x0
376
    state=IDLE, stat=OK [200 = 0xc8]
377
    act_ts=2017-04-19 17:41:41.995884000Z
378
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
379
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
380
	iomode = 3, refcnt = 7, reqs = 0x7fe78d65a8b0, nrecs = 1
381
	flags = 0xa<INCACHE,INUSE>
382
    cPDU@0x7fe789109250: 
383
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
384
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
385
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
386
	rid=3, olen=0, chan=0x0, seqno=0
387
	flags=0
388
	datum=0x0
389
	total header=80
390
    rPDU@0x7fe78d5de430: 
391
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
392
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
393
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
394
	rid=3, olen=24, chan=0x7fe78d6dbbc0, seqno=0
395
	flags=0xa<HAS_RECNO,HAS_TS>
396
	datum=0x7fe78d77da80, recno=1, dbuf=0x7fe78d739c70, dlen=1
397
		ts=2017-04-19 17:41:41.973788000Z
398
	sigmdalg=0x0, siglen=0, sig=0x0
399
	total header=128
400
ep_thr_mutex_lock    gdp_event.c:72 0x15b5a6a20 (&FreeListMutex) [0x70000b553000]
401
ep_thr_mutex_unlock  gdp_event.c:75 0x15b5a6a20 (&FreeListMutex) [0x70000b553000]
402
_gdp_event_new => 0x7fe78d5dc4f0
403
ep_thr_mutex_lock    gdp_datum.c:64 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
404
ep_thr_mutex_unlock  gdp_datum.c:69 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
405
ep_thr_mutex_lock    ep_hash.c:169 0x7fe788b4b830 (&hp->mutex) [0x70000b553000]
406
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe788b4b830 (&hp->mutex) [0x70000b553000]
407
ep_thr_mutex_init    gdp_datum.c:75 0x7fe78d77d4b0 (&datum->mutex) [0x70000b553000]
408
gdp_datum_new => 0x7fe78d77d4b0
409
_gdp_event_trigger: adding event 0x7fe78d5dc4f0 (1) to active list
410
ep_thr_mutex_lock    gdp_event.c:201 0x15b5a6a80 (&ActiveListMutex) [0x70000b553000]
411
ep_thr_cond_broadcast gdp_event.c:203 0x15b5a6ae0 (&ActiveListSig) [0x70000b553000]
412
ep_thr_mutex_unlock  gdp_event.c:204 0x15b5a6a80 (&ActiveListMutex) [0x70000b553000]
413
_gdp_pdu_free(0x7fe78d5de430)
414
gdp_datum_free(0x7fe78d77da80)
415
  ... draining 1 bytes
416
ep_thr_mutex_trylock gdp_datum.c:117 0x7fe78d77da80 (&datum->mutex) [0x70000b553000]
417
gdp_event_next: ep_thr_cond_wait => 0
418
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fe78d77da80 (&datum->mutex) [0x70000b553000]
419
ep_thr_mutex_unlock  gdp_event.c:175 0x15b5a6a80 (&ActiveListMutex) [0x70000c028000]
420
ep_thr_mutex_lock    gdp_datum.c:123 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
421
gdp_event_next => 0x7fe78d5dc4f0
422
ep_thr_mutex_unlock  gdp_datum.c:126 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
423
ep_thr_mutex_lock    gdp_pdu.c:813 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
424
ep_thr_mutex_unlock  gdp_pdu.c:815 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
425
_gdp_req_unlock: req @ 0x7fe789131f60
426
ep_thr_mutex_unlock  gdp_req.c:404 0x7fe789131f60 (&req->mutex) [0x70000b553000]
427
gdp_pdu_proc_resp <<< done
428
gdp_event_free(0x7fe78d5dc4f0)
429
gdp_datum_free(0x7fe78d77d4b0)
430
  ... draining 1 bytes
431
ep_thr_mutex_trylock gdp_datum.c:117 0x7fe78d77d4b0 (&datum->mutex) [0x70000c028000]
432
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fe78d77d4b0 (&datum->mutex) [0x70000c028000]
433
ep_thr_mutex_lock    gdp_datum.c:123 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000c028000]
434
ep_thr_mutex_unlock  gdp_datum.c:126 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000c028000]
435
ep_thr_mutex_lock    gdp_event.c:104 0x15b5a6a20 (&FreeListMutex) [0x70000c028000]
436
ep_thr_mutex_unlock  gdp_event.c:106 0x15b5a6a20 (&FreeListMutex) [0x70000c028000]
437
gdp_event_next: gcl 0x7fe78d4c2c30
438
ep_thr_mutex_lock    gdp_event.c:132 0x15b5a6a80 (&ActiveListMutex) [0x70000c028000]
439
gdp_event_next: empty ActiveList; waiting
440
ep_thr_cond_wait-cv  gdp_event.c:141 0x15b5a6ae0 (&ActiveListSig) [0x70000c028000]
441
ep_thr_cond-wait-mtx gdp_event.c:141 0x15b5a6a80 (&ActiveListSig) [0x70000c028000]
442
gdp_read_cb: fd 126, 88 bytes
443
ep_thr_mutex_lock    gdp_pdu.c:780 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
444
ep_thr_mutex_unlock  gdp_pdu.c:789 0x15b5a6f60 (&PduFreeListMutex) [0x70000b553000]
445
ep_thr_mutex_lock    gdp_datum.c:64 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
446
ep_thr_mutex_unlock  gdp_datum.c:69 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
447
gdp_datum_new => 0x7fe78d77d4b0
448
_gdp_pdu_new => 0x7fe78d5de430
449

    
450
	>>>>>  _gdp_pdu_in  >>>>>
451
_gdp_pdu_in: fixed pdu header:
452
00000000 03 0f 00 81 e8 12 81 57 cd f2 4c 8d d9 2a 4f 79
453
00000010 8c a3 7a 73 ff 95 aa 4e a5 79 2a 66 37 80 a1 cd
454
00000020 4b c0 6a 1c b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea
455
00000030 5b 53 7d 43 d2 41 42 b2 85 67 10 bb b9 17 61 eb
456
00000040 3f 2f 61 6a 00 00 00 00 00 00 02 02 00 00 00 00
457
_gdp_pdu_in: read PDU header:
458
00000000 03 0f 00 81 e8 12 81 57 cd f2 4c 8d d9 2a 4f 79
459
00000010 8c a3 7a 73 ff 95 aa 4e a5 79 2a 66 37 80 a1 cd
460
00000020 4b c0 6a 1c b9 fd 4a 08 a1 96 08 a2 5e 90 3a ea
461
00000030 5b 53 7d 43 d2 41 42 b2 85 67 10 bb b9 17 61 eb
462
00000040 3f 2f 61 6a 00 00 00 00 00 00 02 02 00 00 00 00
463
00000050 00 00 00 00 00 00 00 01
464
_gdp_pdu_in: reading 0 data bytes (0 available)
465
_gdp_pdu_in(ACK_DATA_CREATED) => OK
466
PDU@0x7fe78d5de430: 
467
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
468
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
469
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
470
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
471
	flags=0x2<HAS_RECNO>
472
	datum=0x7fe78d77d4b0, recno=1, dbuf=0x7fe78d780fa0, dlen=0
473
		ts=(none)
474
	sigmdalg=0x0, siglen=0, sig=0x0
475
	total header=96
476

    
477
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 126
478
ep_thr_mutex_lock    ep_hash.c:169 0x7fe78e7f1630 (&hp->mutex) [0x70000b553000]
479
ep_thr_mutex_unlock  ep_hash.c:175 0x7fe78e7f1630 (&hp->mutex) [0x70000b553000]
480
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fe78d4c2c30 (gcl) [0x70000b553000]
481
_gdp_gcl_touch(0x7fe78d4c2c30)
482
_gdp_gcl_incref(0x7fe78d4c2c30): 8
483
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
484
	0x7fe78d4c2c30 refcnt 8
485
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CREATED) gcl 0x7fe78d4c2c30
486
gdp_pdu_proc_resp: searching gcl 0x7fe78d4c2c30 for rid 0
487
_gdp_req_find(gcl=0x7fe78d4c2c30, rid=0)
488
_gdp_req_lock: req @ 0x7fe78d65a8b0
489
ep_thr_mutex_lock    gdp_req.c:383 0x7fe78d65a8b0 (&req->mutex) [0x70000b553000]
490
_gdp_req_find(gcl=0x7fe78d4c2c30, rid=0) => 0x7fe78d65a8b0, state WAITING
491
... found req@0x7fe78d65a8b0:
492
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
493
    postproc=0x0, sub_cb=0x0, udata=0x0
494
    state=WAITING, stat=OK
495
    act_ts=1970-01-01 00:00:00.000000000Z
496
    flags=0x100<ON_CHAN_LIST>
497
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
498
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
499
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
500
    cPDU@0x7fe78d3e8200: 
501
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
502
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
503
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
504
	rid=0, olen=0, chan=0x0, seqno=0
505
	flags=0
506
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=1
507
		ts=(none)
508
	sigmdalg=0x0, siglen=0, sig=0x0
509
	total header=88
510
ep_thr_mutex_unlock  gdp_main.c:410 0x7fe78d4c2c30 (gcl) [0x70000b553000]
511
gdp_pdu_proc_resp: req@0x7fe78d65a8b0:
512
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
513
    postproc=0x0, sub_cb=0x0, udata=0x0
514
    state=WAITING, stat=OK
515
    act_ts=1970-01-01 00:00:00.000000000Z
516
    flags=0x100<ON_CHAN_LIST>
517
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
518
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
519
	flags = 0xa<INCACHE,INUSE>
520
    cPDU@0x7fe78d3e8200: 
521
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
522
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
523
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
524
	rid=0, olen=0, chan=0x0, seqno=0
525
	flags=0
526
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=1
527
		ts=(none)
528
	sigmdalg=0x0, siglen=0, sig=0x0
529
	total header=88
530
    rPDU@0x7fe78d5de430: 
531
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
532
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
533
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
534
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
535
	flags=0x2<HAS_RECNO>
536
	datum=0x7fe78d77d4b0, recno=1, dbuf=0x7fe78d780fa0, dlen=0
537
		ts=(none)
538
	sigmdalg=0x0, siglen=0, sig=0x0
539
	total header=96
540
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 8], req@0x7fe78d65a8b0:
541
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
542
    postproc=0x0, sub_cb=0x0, udata=0x0
543
    state=WAITING, stat=OK
544
    act_ts=2017-04-19 17:41:42.023806000Z
545
    flags=0x100<ON_CHAN_LIST>
546
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
547
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
548
	flags = 0xa<INCACHE,INUSE>
549
    cPDU@0x7fe78d3e8200: 
550
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
551
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
552
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
553
	rid=0, olen=0, chan=0x0, seqno=0
554
	flags=0
555
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=1
556
		ts=(none)
557
	sigmdalg=0x0, siglen=0, sig=0x0
558
	total header=88
559
    rPDU@0x7fe78d5de430: 
560
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
561
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
562
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
563
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
564
	flags=0x2<HAS_RECNO>
565
	datum=0x7fe78d77d4b0, recno=1, dbuf=0x7fe78d780fa0, dlen=0
566
		ts=(none)
567
	sigmdalg=0x0, siglen=0, sig=0x0
568
	total header=96
569

    
570
ack_success: received ACK_DATA_CREATED for CMD_APPEND
571
ack_success: reusing old datum for req 0x7fe78d65a8b0
572
   datum @ 0x7fe78d3d8cc0: recno 1, len 1, no timestamp
573
00000000 31
574
         1 
575
gdp_datum_free(0x7fe78d77d4b0)
576
ep_thr_mutex_trylock gdp_datum.c:117 0x7fe78d77d4b0 (&datum->mutex) [0x70000b553000]
577
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fe78d77d4b0 (&datum->mutex) [0x70000b553000]
578
ep_thr_mutex_lock    gdp_datum.c:123 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
579
ep_thr_mutex_unlock  gdp_datum.c:126 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000b553000]
580
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 8]
581
    OK [201 = 0xc9]
582
    req@0x7fe78d65a8b0:
583
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
584
    postproc=0x0, sub_cb=0x0, udata=0x0
585
    state=WAITING, stat=OK
586
    act_ts=2017-04-19 17:41:42.023954000Z
587
    flags=0x100<ON_CHAN_LIST>
588
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
589
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
590
	flags = 0xa<INCACHE,INUSE>
591
    cPDU@0x7fe78d3e8200: 
592
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
593
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
594
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
595
	rid=0, olen=0, chan=0x0, seqno=0
596
	flags=0
597
	datum=0x0
598
	total header=80
599
    rPDU@0x7fe78d5de430: 
600
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
601
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
602
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
603
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
604
	flags=0x2<HAS_RECNO>
605
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=0
606
		ts=(none)
607
	sigmdalg=0x0, siglen=0, sig=0x0
608
	total header=96
609
acknak_from_estat: OK [201 = 0xc9] -> ACK_DATA_CREATED
610
gdp_pdu_proc_resp(ACK_DATA_CREATED for CMD_APPEND): OK [201 = 0xc9]
611
req@0x7fe78d65a8b0:
612
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
613
    postproc=0x0, sub_cb=0x0, udata=0x0
614
    state=WAITING, stat=OK
615
    act_ts=2017-04-19 17:41:42.023954000Z
616
    flags=0x100<ON_CHAN_LIST>
617
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
618
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
619
	flags = 0xa<INCACHE,INUSE>
620
    cPDU@0x7fe78d3e8200: 
621
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
622
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
623
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
624
	rid=0, olen=0, chan=0x0, seqno=0
625
	flags=0
626
	datum=0x0
627
	total header=80
628
    rPDU@0x7fe78d5de430: 
629
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
630
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
631
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
632
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
633
	flags=0x2<HAS_RECNO>
634
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=0
635
		ts=(none)
636
	sigmdalg=0x0, siglen=0, sig=0x0
637
	total header=96
638
gdp_pdu_proc_resp: signaling req@0x7fe78d65a8b0:
639
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
640
    postproc=0x0, sub_cb=0x0, udata=0x0
641
    state=WAITING, stat=OK [201 = 0xc9]
642
    act_ts=2017-04-19 17:41:42.023954000Z
643
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
644
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
645
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
646
	flags = 0xa<INCACHE,INUSE>
647
    cPDU@0x7fe78d3e8200: 
648
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
649
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
650
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
651
	rid=0, olen=0, chan=0x0, seqno=0
652
	flags=0
653
	datum=0x0
654
	total header=80
655
    rPDU@0x7fe78d5de430: 
656
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
657
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
658
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
659
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
660
	flags=0x2<HAS_RECNO>
661
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=0
662
		ts=(none)
663
	sigmdalg=0x0, siglen=0, sig=0x0
664
	total header=96
665
ep_thr_cond_signal   gdp_main.c:497 0x7fe78d65a900 (&req->cond) [0x70000b553000]
666
ep_thr_yield         gdp_main.c:501 0x0 ((null)) [0x70000b553000]
667
_gdp_req_unlock: req @ 0x7fe78d65a8b0
668
ep_thr_mutex_unlock  gdp_req.c:404 0x7fe78d65a8b0 (&req->mutex) [0x70000b553000]
669
gdp_pdu_proc_resp <<< done
670
_gdp_req_unlock: req @ 0x7fe78d65a8b0
671
ep_thr_mutex_unlock  gdp_req.c:404 0x7fe78d65a8b0 (&req->mutex) [0x70000bd9c000]
672
ep_thr_mutex_lock    gdp_proto.c:153 0x7fe78d4c2c30 (req->gcl) [0x70000bd9c000]
673
_gdp_req_lock: req @ 0x7fe78d65a8b0
674
ep_thr_mutex_lock    gdp_req.c:383 0x7fe78d65a8b0 (&req->mutex) [0x70000bd9c000]
675
_gdp_invoke wait: got 0, done=1, state=2,
676
    stat=OK [201 = 0xc9]
677
_gdp_event_trigger_pending(0x7fe78d65a9c0): empty
678
<<< _gdp_invoke(0x7fe78d65a8b0 rid=0) CMD_APPEND: OK [201 = 0xc9]
679
  req@0x7fe78d65a8b0:
680
    nextrec=0, numrecs=0, chan=0x7fe78d6dbbc0
681
    postproc=0x0, sub_cb=0x0, udata=0x0
682
    state=ACTIVE, stat=OK [201 = 0xc9]
683
    act_ts=2017-04-19 17:41:42.023954000Z
684
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
685
    GCL@0x7fe78d4c2c30: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
686
	iomode = 3, refcnt = 8, reqs = 0x7fe789131f60, nrecs = 1
687
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
688
    cPDU@0x7fe78d3e8200: 
689
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
690
	dst=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
691
	src=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
692
	rid=0, olen=0, chan=0x0, seqno=0
693
	flags=0
694
	datum=0x0
695
	total header=80
696
    rPDU@0x7fe78d5de430: 
697
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
698
	dst=6BKBV83yTI3ZKk95jKN6c_-Vqk6leSpmN4ChzUvAahw
699
	src=uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo
700
	rid=0, olen=8, chan=0x7fe78d6dbbc0, seqno=0
701
	flags=0x2<HAS_RECNO>
702
	datum=0x7fe78d3d8cc0, recno=1, dbuf=0x7fe78d6496d0, dlen=0
703
		ts=(none)
704
	sigmdalg=0x0, siglen=0, sig=0x0
705
	total header=96
706

    
707
_gdp_req_free(0x7fe78d65a8b0)  state=1, gcl=0x7fe78d4c2c30
708
ep_thr_mutex_lock    gdp_req.c:272 0x7fe78d6dbbc0 (&req->chan->mutex) [0x70000bd9c000]
709
ep_thr_mutex_unlock  gdp_req.c:275 0x7fe78d6dbbc0 (&req->chan->mutex) [0x70000bd9c000]
710
_gdp_pdu_free(0x7fe78d5de430)
711
gdp_datum_free(0x7fe78d3d8cc0)
712
  ... draining 0 bytes
713
ep_thr_mutex_trylock gdp_datum.c:117 0x7fe78d3d8cc0 (&datum->mutex) [0x70000bd9c000]
714
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fe78d3d8cc0 (&datum->mutex) [0x70000bd9c000]
715
ep_thr_mutex_lock    gdp_datum.c:123 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
716
ep_thr_mutex_unlock  gdp_datum.c:126 0x15b5a6ce0 (&DatumFreeListMutex) [0x70000bd9c000]
717
ep_thr_mutex_lock    gdp_pdu.c:813 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
718
ep_thr_mutex_unlock  gdp_pdu.c:815 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
719
_gdp_pdu_free(0x7fe78d3e8200)
720
ep_thr_mutex_lock    gdp_pdu.c:813 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
721
ep_thr_mutex_unlock  gdp_pdu.c:815 0x15b5a6f60 (&PduFreeListMutex) [0x70000bd9c000]
722
ep_thr_mutex_lock    gdp_req.c:313 0x15b5a8070 (&ReqFreeListMutex) [0x70000bd9c000]
723
ep_thr_mutex_unlock  gdp_req.c:316 0x15b5a8070 (&ReqFreeListMutex) [0x70000bd9c000]
724
_gdp_req_unlock: req @ 0x7fe78d65a8b0
725
ep_thr_mutex_unlock  gdp_req.c:404 0x7fe78d65a8b0 (&req->mutex) [0x70000bd9c000]
726
ep_thr_mutex_unlock  gdp_api.c:467 0x7fe78d4c2c30 (gcl) [0x70000bd9c000]
727
<<< gdp_gcl_append: OK [201 = 0xc9]
728
GDPLogRead.read(0): start
729
GDPLogRead.read(0): About to call new GDP.GDP()
730
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733, 1, edu.berkeley.eecs.gdp-01.gdplogd): 
731
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
732
GDPManager: gdp settings:
733
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
734
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@5aa42700, 1, org.terraswarm.gdp.GDP_NAME@240c639c)
735
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@5aa42700(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo), RO, org.terraswarm.gdp.GDP_NAME@240c639c(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
736

    
737
>>> gdp_gcl_open(uf1KCKGWCKJekDrqW1N9Q9JBQrKFZxC7uRdh6z8vYWo)
738
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fe78d4c2c30
739
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
740
GDPLogRead.read(0): recno was 0, sending nil
741
GDPHelper.subscribe(): about to call _notifyIncoming {recno=1, data=[B@1b40ebe3, ts=EP_TIME_SPEC(auto-allocated@0x7fe78d5eae20 (16 bytes)) {
742
  long tv_sec@0=58f7a155
743
  int tv_nsec@8=3a0ad360
744
  float tv_accuracy@c=0.0
745
}}
746
****** received: 1
747
****** sent data: 1
748
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733
749
Append data: 2
750
GDPHelper.append(2)
751
_gdp_req_new: allocated new pdu @ 0x7fe78d3e8200
752

    
753
>>> _gdp_invoke(req=0x7fe78d65a8b0 rid=0): CMD_APPEND (71), gcl@0x7fe78d4c2c30
754
	datum @ 0x7fe78d3d8cc0: recno 2, len 1, no timestamp
755
00000000 32
756
         2 
757
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_APPEND
758
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
759

    
760
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 126
761
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CONTENT) gcl 0x7fe78d4c2c30
762
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 10]
763
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
764
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 10]
765
    OK [205 = 0xcd]
766
_gdp_pdu_in(ACK_DATA_CREATED) => OK
767

    
768
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 126
769
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CREATED) gcl 0x7fe78d4c2c30
770
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 11]
771
ack_success: received ACK_DATA_CREATED for CMD_APPEND
772
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 11]
773
    OK [201 = 0xc9]
774
<<< _gdp_invoke(0x7fe78d65a8b0 rid=0) CMD_APPEND: OK [201 = 0xc9]
775
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@339593e7, ts=EP_TIME_SPEC(auto-allocated@0x7fe790c58cc0 (16 bytes)) {
776
  long tv_sec@0=58f7a156
777
  int tv_nsec@8=25a81360
778
  float tv_accuracy@c=0.0
779
}}
780
****** received: 2
781
****** sent data: 2
782
GDPLogRead.read(1): start
783
_gdp_req_new: allocated new pdu @ 0x7fe78d3e8200
784

    
785
>>> _gdp_invoke(req=0x7fe78d65a8b0 rid=0): CMD_READ (70), gcl@0x7fe78d4c2c30
786
	datum @ 0x7fe78d77da80: recno 1, len 0, no timestamp
787
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_READ
788
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
789

    
790
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 126
791
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CONTENT) gcl 0x7fe78d4c2c30
792
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 12]
793
ack_success: received ACK_DATA_CONTENT for CMD_READ
794
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 12]
795
    OK [205 = 0xcd]
796
<<< _gdp_invoke(0x7fe78d65a8b0 rid=0) CMD_READ: OK [205 = 0xcd]
797
GDPLogRead.read(1): sending 1
798
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3305380124895.-306749733
799
Append data: 3
800
GDPHelper.append(3)
801
_gdp_req_new: allocated new pdu @ 0x7fe78d3e8200
802

    
803
>>> _gdp_invoke(req=0x7fe78d65a8b0 rid=0): CMD_APPEND (71), gcl@0x7fe78d4c2c30
804
	datum @ 0x7fe78d77d4b0: recno 2, len 1, no timestamp
805
00000000 33
806
         3 
807
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_APPEND
808
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
809

    
810
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 126
811
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CONTENT) gcl 0x7fe78d4c2c30
812
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 13]
813
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
814
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 13]
815
    OK [205 = 0xcd]
816
_gdp_pdu_in(ACK_DATA_CREATED) => OK
817

    
818
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 126
819
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CREATED) gcl 0x7fe78d4c2c30
820
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 14]
821
ack_success: received ACK_DATA_CREATED for CMD_APPEND
822
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 14]
823
    OK [201 = 0xc9]
824
<<< _gdp_invoke(0x7fe78d65a8b0 rid=0) CMD_APPEND: OK [201 = 0xc9]
825
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@7111a314, ts=EP_TIME_SPEC(auto-allocated@0x7fe78d6b5b00 (16 bytes)) {
826
  long tv_sec@0=58f7a157
827
  int tv_nsec@8=256ba6a0
828
  float tv_accuracy@c=0.0
829
}}
830
****** received: 3
831
****** sent data: 3
832
GDPLogRead.read(2): start
833
_gdp_req_new: allocated new pdu @ 0x7fe78d3e8200
834

    
835
>>> _gdp_invoke(req=0x7fe78d65a8b0 rid=0): CMD_READ (70), gcl@0x7fe78d4c2c30
836
	datum @ 0x7fe793104a90: recno 2, len 0, no timestamp
837
_gdp_pdu_out, fd = 126, basemd = 0x0: CMD_READ
838
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
839

    
840
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 126
841
gdp_pdu_proc_resp(0x7fe78d5de430 ACK_DATA_CONTENT) gcl 0x7fe78d4c2c30
842
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 15]
843
ack_success: received ACK_DATA_CONTENT for CMD_READ
844
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 15]
845
    OK [205 = 0xcd]
846
<<< _gdp_invoke(0x7fe78d65a8b0 rid=0) CMD_READ: OK [205 = 0xcd]
847
GDPLogRead.read(2): sending 3
848

    
849
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
850
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
851

    
852
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
853
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
854

    
855
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
856
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
857

    
858
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
859
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
860
4388 ms. Memory: 587264K Free: 480327K (82%)