Project

General

Profile

subscribeLog.txt

OutputOfPtolemyWithGDPLogging - Anonymous, 04/18/2017 05:18 PM

Download (84.7 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 1572.
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.8976365770414.1434499910, 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@12a5de5, 3, org.terraswarm.gdp.GDP_NAME@5b3243f7)
16
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@12a5de5(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s), RA, org.terraswarm.gdp.GDP_NAME@5b3243f7(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
17

    
18
>>> gdp_gcl_open(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s)
19
_gdp_lib_init(NULL)
20
	@(#)libgdp 0.7.2 (2017-04-18 17:01) f759690d6c300b2ab034867e50baa3dfa9167014
21
My GDP routing name = 6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
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
  0x7fcddfee07e0 [fd  123] Write Persist
30
  0x7fcddfee0760 [fd  123] Read Persist
31
  0x7fcde2b77d20 [fd  -1] Persist Timeout=1492560908.469310
32
Active events:
33
_gdp_req_new: allocated new pdu @ 0x7fcddfee1850
34
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_ADVERTISE
35
gdp_init: OK
36
_gdp_req_new: allocated new pdu @ 0x7fcddfee1850
37

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

    
43
*** Processing ack/nak 240=NAK_R_NOROUTE from socket 123
44
gdp_pdu_proc_resp(0x7fcde2b775d0 NAK_R_NOROUTE) gcl 0x7fcddfee2000
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(0x7fcddfee1930 rid=1) CMD_OPEN_RA: ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
50
Couldn't open GCL xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s:
51
	ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
52
<<< gdp_gcl_open(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s): 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@12a5de5, , org.terraswarm.gdp.GDP_NAME@5b3243f7, {})
55

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

    
61
>>> _gdp_invoke(req=0x7fcddfee1930 rid=2): CMD_CREATE (66), gcl@0x7fcddfee2110
62
	datum @ 0x7fcddfee0da0: recno -1, len 34, no timestamp
63
00000000 c6 64 37 dc 39 6a ab b0 f7 07 43 f7 1d 52 7d d5
64
         ?  d  7  ?  9  j  ?  ?  ?  ?  C  ?  ?  R  }  ? 
65
00000010 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b 9b a5 33 db
66
         ?  c  ?  ?  U  ?  ?  O  -  ?  ?  k  ?  ?  3  ? 
67
00000020 00 00
68
         ?  ? 
69
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_CREATE
70
_gdp_pdu_in(ACK_DATA_CREATED) => OK
71

    
72
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
73
gdp_pdu_proc_resp(0x7fcde2b775d0 ACK_DATA_CREATED) gcl 0x7fcddfee2110
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(0x7fcddfee1930 rid=2) CMD_CREATE: OK [201 = 0xc9]
79
<<< gdp_gcl_create: OK [201 = 0xc9]
80

    
81
>>> gdp_gcl_open(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s)
82
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcddfee2110
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.8976365770414.1434499910, 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@603abf58, 1, org.terraswarm.gdp.GDP_NAME@313fa1ba)
91
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@603abf58(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s), RO, org.terraswarm.gdp.GDP_NAME@313fa1ba(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
92

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

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

    
105
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
106
gdp_pdu_proc_resp(0x7fcde2b775d0 ACK_SUCCESS) gcl 0x7fcddfee2110
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(0x7fcddfee1930 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.8976365770414.1434499910
114
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.8976365770414.1434499910, 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@4addea9e, 2, org.terraswarm.gdp.GDP_NAME@418be79f)
119
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@4addea9e(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s), AO, org.terraswarm.gdp.GDP_NAME@418be79f(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
120

    
121
>>> gdp_gcl_open(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s)
122
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcddfee2110
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 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
127
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
128
gdp_datum_new => 0x7fcddfee0da0
129

    
130
>>> gdp_gcl_append
131
ep_thr_mutex_lock    gdp_api.c:465 0x7fcddfee2110 (gcl) [0x700010677000]
132
ep_thr_mutex_lock    gdp_req.c:139 0x158c83070 (&ReqFreeListMutex) [0x700010677000]
133
ep_thr_mutex_unlock  gdp_req.c:144 0x158c83070 (&ReqFreeListMutex) [0x700010677000]
134
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
135
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
136
ep_thr_mutex_init    gdp_req.c:161 0x7fcddfbdc610 (&req->mutex) [0x700010677000]
137
ep_thr_cond_init     gdp_req.c:163 0x7fcddfbdc660 (&req->cond) [0x700010677000]
138
_gdp_req_lock: req @ 0x7fcddfbdc610
139
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfbdc610 (&req->mutex) [0x700010677000]
140
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
141
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
142
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
143
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
144
gdp_datum_new => 0x7fcde2b77390
145
_gdp_pdu_new => 0x7fcde2b775d0
146
_gdp_req_new: allocated new pdu @ 0x7fcde2b775d0
147
ep_thr_mutex_lock    gdp_req.c:195 0x7fcddfee0690 (&chan->mutex) [0x700010677000]
148
ep_thr_mutex_unlock  gdp_req.c:205 0x7fcddfee0690 (&chan->mutex) [0x700010677000]
149
_gdp_req_new(gcl=0x7fcddfee2110, cmd=CMD_APPEND) => 0x7fcddfbdc610 (rid=0)
150

    
151
>>> _gdp_invoke(req=0x7fcddfbdc610 rid=0): CMD_APPEND (71), gcl@0x7fcddfee2110
152
	datum @ 0x7fcde2b77390: recno 1, len 1, no timestamp
153
00000000 31
154
         1 
155
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
156
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
157
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
158
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
159
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
160
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x700010677000]
161
_gdp_invoke: sending 71, retries=2
162
_gdp_req_send: req@0x7fcddfbdc610:
163
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
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@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
169
	iomode = 3, refcnt = 6, reqs = 0x7fcddfee1930, nrecs = 0
170
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
171
    cPDU@0x7fcde2b775d0: 
172
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
173
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
174
	src=(none)
175
	rid=0, olen=0, chan=0x0, seqno=0
176
	flags=0
177
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, dlen=1
178
		ts=(none)
179
	sigmdalg=0x0, siglen=0, sig=0x0
180
	total header=88
181
_gdp_req_send(0x7fcddfbdc610) gcl=0x7fcddfee2110
182
_gdp_req_send(0x7fcddfee2110) adding to cache
183
_gdp_gcl_cache_add(0x7fcddfee2110): adding
184
_gdp_gcl_cache_add(0x7fcddfee2110): already cached
185
_gdp_pdu_out, fd = 123, basemd = 0x0:
186
    PDU@0x7fcde2b775d0: 
187
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
188
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
189
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
190
	rid=0, olen=0, chan=0x0, seqno=0
191
	flags=0
192
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, 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 c6 64 37 dc 39 6a ab b0 f7 07 43 f7
198
00000010 1d 52 7d d5 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b
199
00000020 9b a5 33 db e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
200
00000030 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
201
00000040 41 73 6f 82 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 0x7fcddfbdc610
206
ep_thr_mutex_unlock  gdp_proto.c:143 0x7fcddfee2110 (req->gcl) [0x700010677000]
207
ep_thr_cond_wait-cv  gdp_proto.c:146 0x7fcddfbdc660 (&req->cond) [0x700010677000]
208
ep_thr_cond-wait-mtx gdp_proto.c:146 0x7fcddfbdc610 (&req->cond) [0x700010677000]
209
gdp_read_cb: fd 123, 105 bytes
210
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
211
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
212
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
213
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
214
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x70000e766000]
215
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x70000e766000]
216
ep_thr_mutex_init    gdp_datum.c:75 0x7fcddbb221e0 (&datum->mutex) [0x70000e766000]
217
gdp_datum_new => 0x7fcddbb221e0
218
_gdp_pdu_new => 0x7fcddbb20490
219

    
220
	>>>>>  _gdp_pdu_in  >>>>>
221
_gdp_pdu_in: fixed pdu header:
222
00000000 03 0f 00 85 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
223
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
224
00000020 41 73 6f 82 c6 64 37 dc 39 6a ab b0 f7 07 43 f7
225
00000030 1d 52 7d d5 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b
226
00000040 9b a5 33 db 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 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
229
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
230
00000020 41 73 6f 82 c6 64 37 dc 39 6a ab b0 f7 07 43 f7
231
00000030 1d 52 7d d5 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b
232
00000040 9b a5 33 db 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 f6 ab ee
234
00000060 25 1d ff b8 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@0x7fcddbb20490: 
240
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
241
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
242
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
243
	rid=3, olen=24, chan=0x7fcddfee0690, seqno=0
244
	flags=0xa<HAS_RECNO,HAS_TS>
245
	datum=0x7fcddbb221e0, recno=1, dbuf=0x7fcddbb22340, dlen=1
246
		ts=2017-04-19 00:14:38.622723000Z
247
	sigmdalg=0x0, siglen=0, sig=0x0
248
	total header=128
249

    
250
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
251
ep_thr_mutex_lock    ep_hash.c:169 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
252
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
253
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fcddfee2110 (gcl) [0x70000e766000]
254
_gdp_gcl_touch(0x7fcddfee2110)
255
_gdp_gcl_incref(0x7fcddfee2110): 7
256
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
257
	0x7fcddfee2110 refcnt 7
258
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CONTENT) gcl 0x7fcddfee2110
259
gdp_pdu_proc_resp: searching gcl 0x7fcddfee2110 for rid 3
260
_gdp_req_find(gcl=0x7fcddfee2110, rid=3)
261
_gdp_req_lock: req @ 0x7fcddfbdc610
262
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
263
_gdp_req_unlock: req @ 0x7fcddfbdc610
264
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
265
_gdp_req_lock: req @ 0x7fcddfee1930
266
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfee1930 (&req->mutex) [0x70000e766000]
267
_gdp_req_find(gcl=0x7fcddfee2110, rid=3) => 0x7fcddfee1930, state IDLE
268
... found req@0x7fcddfee1930:
269
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
270
    postproc=0x0, sub_cb=0x0, udata=0x0
271
    state=IDLE, stat=OK [200 = 0xc8]
272
    act_ts=2017-04-19 00:14:38.606167000Z
273
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
274
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
275
	iomode = 3, refcnt = 7, reqs = 0x7fcddfbdc610, nrecs = 0
276
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
277
    cPDU@0x7fcddfee1850: 
278
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
279
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
280
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
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 0x7fcddfee2110 (gcl) [0x70000e766000]
286
gdp_pdu_proc_resp: req@0x7fcddfee1930:
287
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
288
    postproc=0x0, sub_cb=0x0, udata=0x0
289
    state=IDLE, stat=OK [200 = 0xc8]
290
    act_ts=2017-04-19 00:14:38.606167000Z
291
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
292
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
293
	iomode = 3, refcnt = 7, reqs = 0x7fcddfbdc610, nrecs = 0
294
	flags = 0xa<INCACHE,INUSE>
295
    cPDU@0x7fcddfee1850: 
296
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
297
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
298
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
299
	rid=3, olen=0, chan=0x0, seqno=0
300
	flags=0
301
	datum=0x0
302
	total header=80
303
    rPDU@0x7fcddbb20490: 
304
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
305
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
306
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
307
	rid=3, olen=24, chan=0x7fcddfee0690, seqno=0
308
	flags=0xa<HAS_RECNO,HAS_TS>
309
	datum=0x7fcddbb221e0, recno=1, dbuf=0x7fcddbb22340, dlen=1
310
		ts=2017-04-19 00:14:38.622723000Z
311
	sigmdalg=0x0, siglen=0, sig=0x0
312
	total header=128
313
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 7], req@0x7fcddfee1930:
314
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
315
    postproc=0x0, sub_cb=0x0, udata=0x0
316
    state=IDLE, stat=OK [200 = 0xc8]
317
    act_ts=2017-04-19 00:14:38.639194000Z
318
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
319
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
320
	iomode = 3, refcnt = 7, reqs = 0x7fcddfbdc610, nrecs = 0
321
	flags = 0xa<INCACHE,INUSE>
322
    cPDU@0x7fcddfee1850: 
323
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
324
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
325
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
326
	rid=3, olen=0, chan=0x0, seqno=0
327
	flags=0
328
	datum=0x0
329
	total header=80
330
    rPDU@0x7fcddbb20490: 
331
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
332
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
333
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
334
	rid=3, olen=24, chan=0x7fcddfee0690, seqno=0
335
	flags=0xa<HAS_RECNO,HAS_TS>
336
	datum=0x7fcddbb221e0, recno=1, dbuf=0x7fcddbb22340, dlen=1
337
		ts=2017-04-19 00:14:38.622723000Z
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@0x7fcddfee1930:
345
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
346
    postproc=0x0, sub_cb=0x0, udata=0x0
347
    state=IDLE, stat=OK [200 = 0xc8]
348
    act_ts=2017-04-19 00:14:38.639255000Z
349
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
350
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
351
	iomode = 3, refcnt = 7, reqs = 0x7fcddfbdc610, nrecs = 1
352
	flags = 0xa<INCACHE,INUSE>
353
    cPDU@0x7fcddfee1850: 
354
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
355
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
356
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
357
	rid=3, olen=0, chan=0x0, seqno=0
358
	flags=0
359
	datum=0x0
360
	total header=80
361
    rPDU@0x7fcddbb20490: 
362
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
363
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
364
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
365
	rid=3, olen=24, chan=0x7fcddfee0690, seqno=0
366
	flags=0xa<HAS_RECNO,HAS_TS>
367
	datum=0x7fcddbb221e0, recno=1, dbuf=0x7fcddbb22340, dlen=1
368
		ts=2017-04-19 00:14:38.622723000Z
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@0x7fcddfee1930:
374
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
375
    postproc=0x0, sub_cb=0x0, udata=0x0
376
    state=IDLE, stat=OK [200 = 0xc8]
377
    act_ts=2017-04-19 00:14:38.639255000Z
378
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
379
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
380
	iomode = 3, refcnt = 7, reqs = 0x7fcddfbdc610, nrecs = 1
381
	flags = 0xa<INCACHE,INUSE>
382
    cPDU@0x7fcddfee1850: 
383
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
384
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
385
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
386
	rid=3, olen=0, chan=0x0, seqno=0
387
	flags=0
388
	datum=0x0
389
	total header=80
390
    rPDU@0x7fcddbb20490: 
391
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
392
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
393
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
394
	rid=3, olen=24, chan=0x7fcddfee0690, seqno=0
395
	flags=0xa<HAS_RECNO,HAS_TS>
396
	datum=0x7fcddbb221e0, recno=1, dbuf=0x7fcddbb22340, dlen=1
397
		ts=2017-04-19 00:14:38.622723000Z
398
	sigmdalg=0x0, siglen=0, sig=0x0
399
	total header=128
400
ep_thr_mutex_lock    gdp_event.c:72 0x158c81a20 (&FreeListMutex) [0x70000e766000]
401
ep_thr_mutex_unlock  gdp_event.c:75 0x158c81a20 (&FreeListMutex) [0x70000e766000]
402
_gdp_event_new => 0x7fcddb905b00
403
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
404
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
405
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x70000e766000]
406
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x70000e766000]
407
ep_thr_mutex_init    gdp_datum.c:75 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
408
gdp_datum_new => 0x7fcddb924820
409
_gdp_event_trigger: adding event 0x7fcddb905b00 (1) to active list
410
ep_thr_mutex_lock    gdp_event.c:201 0x158c81a80 (&ActiveListMutex) [0x70000e766000]
411
ep_thr_cond_broadcast gdp_event.c:203 0x158c81ae0 (&ActiveListSig) [0x70000e766000]
412
ep_thr_mutex_unlock  gdp_event.c:204 0x158c81a80 (&ActiveListMutex) [0x70000e766000]
413
_gdp_pdu_free(0x7fcddbb20490)
414
gdp_datum_free(0x7fcddbb221e0)
415
  ... draining 1 bytes
416
gdp_event_next: ep_thr_cond_wait => 0
417
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddbb221e0 (&datum->mutex) [0x70000e766000]
418
ep_thr_mutex_unlock  gdp_event.c:175 0x158c81a80 (&ActiveListMutex) [0x70001077a000]
419
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddbb221e0 (&datum->mutex) [0x70000e766000]
420
gdp_event_next => 0x7fcddb905b00
421
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
422
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
423
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
424
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
425
_gdp_req_unlock: req @ 0x7fcddfee1930
426
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfee1930 (&req->mutex) [0x70000e766000]
427
gdp_pdu_proc_resp <<< done
428
gdp_event_free(0x7fcddb905b00)
429
gdp_datum_free(0x7fcddb924820)
430
  ... draining 1 bytes
431
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddb924820 (&datum->mutex) [0x70001077a000]
432
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddb924820 (&datum->mutex) [0x70001077a000]
433
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70001077a000]
434
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70001077a000]
435
ep_thr_mutex_lock    gdp_event.c:104 0x158c81a20 (&FreeListMutex) [0x70001077a000]
436
ep_thr_mutex_unlock  gdp_event.c:106 0x158c81a20 (&FreeListMutex) [0x70001077a000]
437
gdp_event_next: gcl 0x7fcddfee2110
438
ep_thr_mutex_lock    gdp_event.c:132 0x158c81a80 (&ActiveListMutex) [0x70001077a000]
439
gdp_event_next: empty ActiveList; waiting
440
ep_thr_cond_wait-cv  gdp_event.c:141 0x158c81ae0 (&ActiveListSig) [0x70001077a000]
441
ep_thr_cond-wait-mtx gdp_event.c:141 0x158c81a80 (&ActiveListSig) [0x70001077a000]
442
gdp_read_cb: fd 123, 88 bytes
443
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
444
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
445
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
446
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
447
gdp_datum_new => 0x7fcddb924820
448
_gdp_pdu_new => 0x7fcddbb20490
449

    
450
	>>>>>  _gdp_pdu_in  >>>>>
451
_gdp_pdu_in: fixed pdu header:
452
00000000 03 0f 00 81 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
453
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
454
00000020 41 73 6f 82 c6 64 37 dc 39 6a ab b0 f7 07 43 f7
455
00000030 1d 52 7d d5 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b
456
00000040 9b a5 33 db 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 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
459
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
460
00000020 41 73 6f 82 c6 64 37 dc 39 6a ab b0 f7 07 43 f7
461
00000030 1d 52 7d d5 fe 63 bd ee 55 de b4 4f 2d 84 f5 6b
462
00000040 9b a5 33 db 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@0x7fcddbb20490: 
467
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
468
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
469
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
470
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
471
	flags=0x2<HAS_RECNO>
472
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcddb908350, 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 123
478
ep_thr_mutex_lock    ep_hash.c:169 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
479
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
480
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fcddfee2110 (gcl) [0x70000e766000]
481
_gdp_gcl_touch(0x7fcddfee2110)
482
_gdp_gcl_incref(0x7fcddfee2110): 8
483
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
484
	0x7fcddfee2110 refcnt 8
485
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CREATED) gcl 0x7fcddfee2110
486
gdp_pdu_proc_resp: searching gcl 0x7fcddfee2110 for rid 0
487
_gdp_req_find(gcl=0x7fcddfee2110, rid=0)
488
_gdp_req_lock: req @ 0x7fcddfbdc610
489
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
490
_gdp_req_find(gcl=0x7fcddfee2110, rid=0) => 0x7fcddfbdc610, state WAITING
491
... found req@0x7fcddfbdc610:
492
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
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@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
498
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
499
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
500
    cPDU@0x7fcde2b775d0: 
501
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
502
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
503
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
504
	rid=0, olen=0, chan=0x0, seqno=0
505
	flags=0
506
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, 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 0x7fcddfee2110 (gcl) [0x70000e766000]
511
gdp_pdu_proc_resp: req@0x7fcddfbdc610:
512
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
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@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
518
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
519
	flags = 0xa<INCACHE,INUSE>
520
    cPDU@0x7fcde2b775d0: 
521
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
522
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
523
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
524
	rid=0, olen=0, chan=0x0, seqno=0
525
	flags=0
526
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, dlen=1
527
		ts=(none)
528
	sigmdalg=0x0, siglen=0, sig=0x0
529
	total header=88
530
    rPDU@0x7fcddbb20490: 
531
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
532
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
533
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
534
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
535
	flags=0x2<HAS_RECNO>
536
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcddb908350, 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@0x7fcddfbdc610:
541
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
542
    postproc=0x0, sub_cb=0x0, udata=0x0
543
    state=WAITING, stat=OK
544
    act_ts=2017-04-19 00:14:38.678084000Z
545
    flags=0x100<ON_CHAN_LIST>
546
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
547
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
548
	flags = 0xa<INCACHE,INUSE>
549
    cPDU@0x7fcde2b775d0: 
550
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
551
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
552
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
553
	rid=0, olen=0, chan=0x0, seqno=0
554
	flags=0
555
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, dlen=1
556
		ts=(none)
557
	sigmdalg=0x0, siglen=0, sig=0x0
558
	total header=88
559
    rPDU@0x7fcddbb20490: 
560
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
561
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
562
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
563
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
564
	flags=0x2<HAS_RECNO>
565
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcddb908350, 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 0x7fcddfbdc610
572
   datum @ 0x7fcde2b77390: recno 1, len 1, no timestamp
573
00000000 31
574
         1 
575
gdp_datum_free(0x7fcddb924820)
576
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
577
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
578
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
579
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
580
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 8]
581
    OK [201 = 0xc9]
582
    req@0x7fcddfbdc610:
583
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
584
    postproc=0x0, sub_cb=0x0, udata=0x0
585
    state=WAITING, stat=OK
586
    act_ts=2017-04-19 00:14:38.678176000Z
587
    flags=0x100<ON_CHAN_LIST>
588
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
589
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
590
	flags = 0xa<INCACHE,INUSE>
591
    cPDU@0x7fcde2b775d0: 
592
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
593
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
594
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
595
	rid=0, olen=0, chan=0x0, seqno=0
596
	flags=0
597
	datum=0x0
598
	total header=80
599
    rPDU@0x7fcddbb20490: 
600
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
601
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
602
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
603
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
604
	flags=0x2<HAS_RECNO>
605
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, 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@0x7fcddfbdc610:
612
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
613
    postproc=0x0, sub_cb=0x0, udata=0x0
614
    state=WAITING, stat=OK
615
    act_ts=2017-04-19 00:14:38.678176000Z
616
    flags=0x100<ON_CHAN_LIST>
617
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
618
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
619
	flags = 0xa<INCACHE,INUSE>
620
    cPDU@0x7fcde2b775d0: 
621
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
622
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
623
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
624
	rid=0, olen=0, chan=0x0, seqno=0
625
	flags=0
626
	datum=0x0
627
	total header=80
628
    rPDU@0x7fcddbb20490: 
629
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
630
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
631
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
632
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
633
	flags=0x2<HAS_RECNO>
634
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, dlen=0
635
		ts=(none)
636
	sigmdalg=0x0, siglen=0, sig=0x0
637
	total header=96
638
gdp_pdu_proc_resp: signaling req@0x7fcddfbdc610:
639
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
640
    postproc=0x0, sub_cb=0x0, udata=0x0
641
    state=WAITING, stat=OK [201 = 0xc9]
642
    act_ts=2017-04-19 00:14:38.678176000Z
643
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
644
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
645
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
646
	flags = 0xa<INCACHE,INUSE>
647
    cPDU@0x7fcde2b775d0: 
648
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
649
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
650
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
651
	rid=0, olen=0, chan=0x0, seqno=0
652
	flags=0
653
	datum=0x0
654
	total header=80
655
    rPDU@0x7fcddbb20490: 
656
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
657
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
658
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
659
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
660
	flags=0x2<HAS_RECNO>
661
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, 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 0x7fcddfbdc660 (&req->cond) [0x70000e766000]
666
ep_thr_yield         gdp_main.c:501 0x0 ((null)) [0x70000e766000]
667
_gdp_req_unlock: req @ 0x7fcddfbdc610
668
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
669
gdp_pdu_proc_resp <<< done
670
_gdp_req_unlock: req @ 0x7fcddfbdc610
671
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfbdc610 (&req->mutex) [0x700010677000]
672
ep_thr_mutex_lock    gdp_proto.c:153 0x7fcddfee2110 (req->gcl) [0x700010677000]
673
_gdp_req_lock: req @ 0x7fcddfbdc610
674
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfbdc610 (&req->mutex) [0x700010677000]
675
_gdp_invoke wait: got 0, done=1, state=2,
676
    stat=OK [201 = 0xc9]
677
_gdp_event_trigger_pending(0x7fcddfbdc720): empty
678
<<< _gdp_invoke(0x7fcddfbdc610 rid=0) CMD_APPEND: OK [201 = 0xc9]
679
  req@0x7fcddfbdc610:
680
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
681
    postproc=0x0, sub_cb=0x0, udata=0x0
682
    state=ACTIVE, stat=OK [201 = 0xc9]
683
    act_ts=2017-04-19 00:14:38.678176000Z
684
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
685
    GCL@0x7fcddfee2110: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
686
	iomode = 3, refcnt = 8, reqs = 0x7fcddfee1930, nrecs = 1
687
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
688
    cPDU@0x7fcde2b775d0: 
689
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
690
	dst=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
691
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
692
	rid=0, olen=0, chan=0x0, seqno=0
693
	flags=0
694
	datum=0x0
695
	total header=80
696
    rPDU@0x7fcddbb20490: 
697
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
698
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
699
	src=xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s
700
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
701
	flags=0x2<HAS_RECNO>
702
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcddff31630, dlen=0
703
		ts=(none)
704
	sigmdalg=0x0, siglen=0, sig=0x0
705
	total header=96
706

    
707
_gdp_req_free(0x7fcddfbdc610)  state=1, gcl=0x7fcddfee2110
708
ep_thr_mutex_lock    gdp_req.c:272 0x7fcddfee0690 (&req->chan->mutex) [0x700010677000]
709
ep_thr_mutex_unlock  gdp_req.c:275 0x7fcddfee0690 (&req->chan->mutex) [0x700010677000]
710
_gdp_pdu_free(0x7fcddbb20490)
711
gdp_datum_free(0x7fcde2b77390)
712
  ... draining 0 bytes
713
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcde2b77390 (&datum->mutex) [0x700010677000]
714
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcde2b77390 (&datum->mutex) [0x700010677000]
715
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
716
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x700010677000]
717
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
718
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
719
_gdp_pdu_free(0x7fcde2b775d0)
720
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
721
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x700010677000]
722
ep_thr_mutex_lock    gdp_req.c:313 0x158c83070 (&ReqFreeListMutex) [0x700010677000]
723
ep_thr_mutex_unlock  gdp_req.c:316 0x158c83070 (&ReqFreeListMutex) [0x700010677000]
724
_gdp_req_unlock: req @ 0x7fcddfbdc610
725
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfbdc610 (&req->mutex) [0x700010677000]
726
ep_thr_mutex_unlock  gdp_api.c:467 0x7fcddfee2110 (gcl) [0x700010677000]
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.8976365770414.1434499910, 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@43d5fa02, 1, org.terraswarm.gdp.GDP_NAME@50a5e12a)
735
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@43d5fa02(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s), RO, org.terraswarm.gdp.GDP_NAME@50a5e12a(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
736

    
737
>>> gdp_gcl_open(xmQ33Dlqq7D3B0P3HVJ91f5jve5V3rRPLYT1a5ulM9s)
738
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcddfee2110
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@3131f483, ts=EP_TIME_SPEC(auto-allocated@0x7fcddba04ab0 (16 bytes)) {
742
  long tv_sec@0=58f6abee
743
  int tv_nsec@8=251dffb8
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.8976365770414.1434499910
749
Append data: 2
750
GDPHelper.append(2)
751
_gdp_req_new: allocated new pdu @ 0x7fcde2b775d0
752

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

    
760
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
761
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CONTENT) gcl 0x7fcddfee2110
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 123
769
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CREATED) gcl 0x7fcddfee2110
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(0x7fcddfbdc610 rid=0) CMD_APPEND: OK [201 = 0xc9]
775
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@9768fa2, ts=EP_TIME_SPEC(auto-allocated@0x7fcddffaa8b0 (16 bytes)) {
776
  long tv_sec@0=58f6abef
777
  int tv_nsec@8=179b1740
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 @ 0x7fcde2b775d0
784

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

    
790
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
791
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CONTENT) gcl 0x7fcddfee2110
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(0x7fcddfbdc610 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.8976365770414.1434499910
799
Append data: 3
800
GDPHelper.append(3)
801
_gdp_req_new: allocated new pdu @ 0x7fcde2b775d0
802

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

    
810
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
811
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CONTENT) gcl 0x7fcddfee2110
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 123
819
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CREATED) gcl 0x7fcddfee2110
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(0x7fcddfbdc610 rid=0) CMD_APPEND: OK [201 = 0xc9]
825
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@7649a451, ts=EP_TIME_SPEC(auto-allocated@0x7fcddffa7840 (16 bytes)) {
826
  long tv_sec@0=58f6abf0
827
  int tv_nsec@8=1770d2f0
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 @ 0x7fcde2b775d0
834

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

    
840
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
841
gdp_pdu_proc_resp(0x7fcddbb20490 ACK_DATA_CONTENT) gcl 0x7fcddfee2110
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(0x7fcddfbdc610 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
4405 ms. Memory: 524800K Free: 405550K (77%)
861

    
862
>>> _gdp_invoke(req=0x7fcddfee1930 rid=3): CMD_SUBSCRIBE (72), gcl@0x7fcddfee2110
863
	datum @ 0x7fcddffaf6e0: recno 3, len 4, no timestamp
864
00000000 00 00 00 00
865
         ?  ?  ?  ? 
866
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_SUBSCRIBE
867
_gdp_pdu_in(ACK_SUCCESS) => OK
868

    
869
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
870
gdp_pdu_proc_resp(0x7fcde2b775d0 ACK_SUCCESS) gcl 0x7fcddfee2110
871
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 16]
872
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
873
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 16]
874
    OK [200 = 0xc8]
875
<<< _gdp_invoke(0x7fcddfee1930 rid=3) CMD_SUBSCRIBE: OK [200 = 0xc8]
876
subscr_resub(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U) ->
877
	OK [200 = 0xc8]
878
Warning: '.GDPLogSubscribe.Test' is in training mode, set the trainingMode parameter to false before checking in
879
GDPLogCreate.js: initialize()
880
Warning: '.GDPLogSubscribe.Test2' is in training mode, set the trainingMode parameter to false before checking in
881
GDPLogAppend.js: initialize()
882
GDPLogCreate.js: create() Start.
883
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023, 3, edu.berkeley.eecs.gdp-01.gdplogd): 
884
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
885
GDPManager: gdp settings:
886
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
887
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@118f6781, 3, org.terraswarm.gdp.GDP_NAME@4aa0610)
888
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@118f6781(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI), RA, org.terraswarm.gdp.GDP_NAME@4aa0610(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
889

    
890
>>> gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI)
891
_gdp_req_new: allocated new pdu @ 0x7fcddbb20490
892

    
893
>>> _gdp_invoke(req=0x7fcddfbdc610 rid=4): CMD_OPEN_RA (75), gcl@0x7fcde2b2fbd0
894
	datum @ 0x7fcddbb221e0: recno -1, len 0, no timestamp
895
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_OPEN_RA
896
_gdp_pdu_in(NAK_R_NOROUTE) => OK
897

    
898
*** Processing ack/nak 240=NAK_R_NOROUTE from socket 123
899
gdp_pdu_proc_resp(0x7fcddff47cc0 NAK_R_NOROUTE) gcl 0x7fcde2b2fbd0
900
_gdp_req_dispatch >>> NAK_R_NOROUTE (240) [gcl->refcnt 2]
901
nak_router: received NAK_R_NOROUTE for CMD_OPEN_RA
902
_gdp_req_dispatch <<< NAK_R_NOROUTE [gcl->refcnt 2]
903
    ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
904
<<< _gdp_invoke(0x7fcddfbdc610 rid=4) CMD_OPEN_RA: ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
905
Couldn't open GCL 9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI:
906
	ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
907
<<< gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI): ERROR: 600 no route available [Berkeley:Swarm-GDP:600]
908
GDP_GCL: gdp_gcl_open() failed, trying to create the log and call gdp_gcl_open() again.
909
GDP_GCL.java: create(org.terraswarm.gdp.GDP_NAME@118f6781, , org.terraswarm.gdp.GDP_NAME@4aa0610, {})
910

    
911
>>> gdp_gcl_create
912
_gdp_gcl_create: gcl=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
913
	logd=m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
914
_gdp_req_new: allocated new pdu @ 0x7fcddbb20490
915

    
916
>>> _gdp_invoke(req=0x7fcddfbdc610 rid=5): CMD_CREATE (66), gcl@0x7fcde2b2fbd0
917
	datum @ 0x7fcddbb221e0: recno -1, len 34, no timestamp
918
00000000 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b e7 55 90 84
919
         ?  ?  ?  ?  _  ?  F  ?  m  ?  ?  [  ?  U  ?  ? 
920
00000010 72 97 22 9a 3b 1f 2f 05 10 b4 de 11 68 82 24 42
921
         r  ?  "  ?  ;  ?  /  ?  ?  ?  ?  ?  h  ?  $  B 
922
00000020 00 00
923
         ?  ? 
924
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_CREATE
925
_gdp_pdu_in(ACK_DATA_CREATED) => OK
926

    
927
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
928
gdp_pdu_proc_resp(0x7fcddff47cc0 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
929
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 2]
930
ack_success: received ACK_DATA_CREATED for CMD_CREATE
931
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 2]
932
    OK [201 = 0xc9]
933
<<< _gdp_invoke(0x7fcddfbdc610 rid=5) CMD_CREATE: OK [201 = 0xc9]
934
<<< gdp_gcl_create: OK [201 = 0xc9]
935

    
936
>>> gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI)
937
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcde2b2fbd0
938
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
939

    
940
GDPLogCreate.js: create() Done!
941
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023, 1, edu.berkeley.eecs.gdp-01.gdplogd): 
942
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
943
GDPManager: gdp settings:
944
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
945
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@4be64f90, 1, org.terraswarm.gdp.GDP_NAME@50aa8c52)
946
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@4be64f90(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI), RO, org.terraswarm.gdp.GDP_NAME@50aa8c52(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
947

    
948
>>> gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI)
949
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcde2b2fbd0
950
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
951
_gdp_req_new: allocated new pdu @ 0x7fcddbb20490
952

    
953
>>> _gdp_invoke(req=0x7fcddfbdc610 rid=6): CMD_SUBSCRIBE (72), gcl@0x7fcde2b2fbd0
954
	datum @ 0x7fcddbb221e0: recno 0, len 4, no timestamp
955
00000000 00 00 00 00
956
         ?  ?  ?  ? 
957
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_SUBSCRIBE
958
_gdp_pdu_in(ACK_SUCCESS) => OK
959

    
960
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
961
gdp_pdu_proc_resp(0x7fcddff47cc0 ACK_SUCCESS) gcl 0x7fcde2b2fbd0
962
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 5]
963
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
964
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 5]
965
    OK [200 = 0xc8]
966
<<< _gdp_invoke(0x7fcddfbdc610 rid=6) CMD_SUBSCRIBE: OK [200 = 0xc8]
967
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023
968
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023, 2, edu.berkeley.eecs.gdp-01.gdplogd): 
969
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
970
GDPManager: gdp settings:
971
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
972
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@30a2a036, 2, org.terraswarm.gdp.GDP_NAME@4179d0bc)
973
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@30a2a036(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI), AO, org.terraswarm.gdp.GDP_NAME@4179d0bc(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
974

    
975
>>> gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI)
976
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcde2b2fbd0
977
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
978
Append data: 1
979
GDPHelper.append(1)
980
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
981
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
982
gdp_datum_new => 0x7fcddbb221e0
983

    
984
>>> gdp_gcl_append
985
ep_thr_mutex_lock    gdp_api.c:465 0x7fcde2b2fbd0 (gcl) [0x7000107fd000]
986
ep_thr_mutex_lock    gdp_req.c:139 0x158c83070 (&ReqFreeListMutex) [0x7000107fd000]
987
ep_thr_mutex_unlock  gdp_req.c:144 0x158c83070 (&ReqFreeListMutex) [0x7000107fd000]
988
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
989
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
990
ep_thr_mutex_init    gdp_req.c:161 0x7fcdd9507460 (&req->mutex) [0x7000107fd000]
991
ep_thr_cond_init     gdp_req.c:163 0x7fcdd95074b0 (&req->cond) [0x7000107fd000]
992
_gdp_req_lock: req @ 0x7fcdd9507460
993
ep_thr_mutex_lock    gdp_req.c:383 0x7fcdd9507460 (&req->mutex) [0x7000107fd000]
994
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
995
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
996
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
997
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
998
gdp_datum_new => 0x7fcde2b77390
999
_gdp_pdu_new => 0x7fcddff47cc0
1000
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1001
ep_thr_mutex_lock    gdp_req.c:195 0x7fcddfee0690 (&chan->mutex) [0x7000107fd000]
1002
ep_thr_mutex_unlock  gdp_req.c:205 0x7fcddfee0690 (&chan->mutex) [0x7000107fd000]
1003
_gdp_req_new(gcl=0x7fcde2b2fbd0, cmd=CMD_APPEND) => 0x7fcdd9507460 (rid=0)
1004

    
1005
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_APPEND (71), gcl@0x7fcde2b2fbd0
1006
	datum @ 0x7fcde2b77390: recno 1, len 1, no timestamp
1007
00000000 31
1008
         1 
1009
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1010
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1011
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1012
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1013
ep_thr_mutex_lock    ep_hash.c:169 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1014
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcdd9f8ae30 (&hp->mutex) [0x7000107fd000]
1015
_gdp_invoke: sending 71, retries=2
1016
_gdp_req_send: req@0x7fcdd9507460:
1017
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1018
    postproc=0x0, sub_cb=0x0, udata=0x0
1019
    state=ACTIVE, stat=OK
1020
    act_ts=1970-01-01 00:00:00.000000000Z
1021
    flags=0x100<ON_CHAN_LIST>
1022
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1023
	iomode = 3, refcnt = 6, reqs = 0x7fcddfbdc610, nrecs = 0
1024
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
1025
    cPDU@0x7fcddff47cc0: 
1026
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1027
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1028
	src=(none)
1029
	rid=0, olen=0, chan=0x0, seqno=0
1030
	flags=0
1031
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=1
1032
		ts=(none)
1033
	sigmdalg=0x0, siglen=0, sig=0x0
1034
	total header=88
1035
_gdp_req_send(0x7fcdd9507460) gcl=0x7fcde2b2fbd0
1036
_gdp_req_send(0x7fcde2b2fbd0) adding to cache
1037
_gdp_gcl_cache_add(0x7fcde2b2fbd0): adding
1038
_gdp_gcl_cache_add(0x7fcde2b2fbd0): already cached
1039
_gdp_pdu_out, fd = 123, basemd = 0x0:
1040
    PDU@0x7fcddff47cc0: 
1041
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1042
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1043
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1044
	rid=0, olen=0, chan=0x0, seqno=0
1045
	flags=0
1046
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=1
1047
		ts=(none)
1048
	sigmdalg=0x0, siglen=0, sig=0x0
1049
	total header=88
1050
_gdp_pdu_out: sending PDU:
1051
00000000 03 0f 00 47 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b
1052
00000010 e7 55 90 84 72 97 22 9a 3b 1f 2f 05 10 b4 de 11
1053
00000020 68 82 24 42 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
1054
00000030 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
1055
00000040 41 73 6f 82 00 00 00 00 00 00 02 02 00 00 00 01
1056
00000050 00 00 00 00 00 00 00 01
1057
00000058                         31
1058
                                 1 
1059
_gdp_invoke: waiting on 0x7fcdd9507460
1060
ep_thr_mutex_unlock  gdp_proto.c:143 0x7fcde2b2fbd0 (req->gcl) [0x7000107fd000]
1061
ep_thr_cond_wait-cv  gdp_proto.c:146 0x7fcdd95074b0 (&req->cond) [0x7000107fd000]
1062
ep_thr_cond-wait-mtx gdp_proto.c:146 0x7fcdd9507460 (&req->cond) [0x7000107fd000]
1063
gdp_read_cb: fd 123, 105 bytes
1064
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1065
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1066
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1067
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1068
gdp_datum_new => 0x7fcddb924820
1069
_gdp_pdu_new => 0x7fcddfbe9860
1070

    
1071
	>>>>>  _gdp_pdu_in  >>>>>
1072
_gdp_pdu_in: fixed pdu header:
1073
00000000 03 0f 00 85 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
1074
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
1075
00000020 41 73 6f 82 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b
1076
00000030 e7 55 90 84 72 97 22 9a 3b 1f 2f 05 10 b4 de 11
1077
00000040 68 82 24 42 00 00 00 06 00 00 06 0a 00 00 00 01
1078
_gdp_pdu_in: read PDU header:
1079
00000000 03 0f 00 85 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
1080
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
1081
00000020 41 73 6f 82 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b
1082
00000030 e7 55 90 84 72 97 22 9a 3b 1f 2f 05 10 b4 de 11
1083
00000040 68 82 24 42 00 00 00 06 00 00 06 0a 00 00 00 01
1084
00000050 00 00 00 00 00 00 00 01 00 00 00 00 58 f6 ac 4c
1085
00000060 00 82 9d 80 00 00 00 00
1086
_gdp_pdu_in: reading 1 data bytes (1 available)
1087
00000068                         31
1088
                                 1 
1089
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1090
PDU@0x7fcddfbe9860: 
1091
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
1092
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1093
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1094
	rid=6, olen=24, chan=0x7fcddfee0690, seqno=0
1095
	flags=0xa<HAS_RECNO,HAS_TS>
1096
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=1
1097
		ts=2017-04-19 00:16:12.008560000Z
1098
	sigmdalg=0x0, siglen=0, sig=0x0
1099
	total header=128
1100

    
1101
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1102
ep_thr_mutex_lock    ep_hash.c:169 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
1103
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
1104
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fcde2b2fbd0 (gcl) [0x70000e766000]
1105
_gdp_gcl_touch(0x7fcde2b2fbd0)
1106
_gdp_gcl_incref(0x7fcde2b2fbd0): 7
1107
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
1108
	0x7fcde2b2fbd0 refcnt 7
1109
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1110
gdp_pdu_proc_resp: searching gcl 0x7fcde2b2fbd0 for rid 6
1111
_gdp_req_find(gcl=0x7fcde2b2fbd0, rid=6)
1112
_gdp_req_lock: req @ 0x7fcdd9507460
1113
ep_thr_mutex_lock    gdp_req.c:383 0x7fcdd9507460 (&req->mutex) [0x70000e766000]
1114
_gdp_req_unlock: req @ 0x7fcdd9507460
1115
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcdd9507460 (&req->mutex) [0x70000e766000]
1116
_gdp_req_lock: req @ 0x7fcddfbdc610
1117
ep_thr_mutex_lock    gdp_req.c:383 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
1118
_gdp_req_find(gcl=0x7fcde2b2fbd0, rid=6) => 0x7fcddfbdc610, state IDLE
1119
... found req@0x7fcddfbdc610:
1120
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1121
    postproc=0x0, sub_cb=0x0, udata=0x0
1122
    state=IDLE, stat=OK [200 = 0xc8]
1123
    act_ts=2017-04-19 00:16:11.981942000Z
1124
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
1125
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1126
	iomode = 3, refcnt = 7, reqs = 0x7fcdd9507460, nrecs = 0
1127
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
1128
    cPDU@0x7fcddbb20490: 
1129
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
1130
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1131
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1132
	rid=6, olen=0, chan=0x0, seqno=0
1133
	flags=0
1134
	datum=0x0
1135
	total header=80
1136
ep_thr_mutex_unlock  gdp_main.c:410 0x7fcde2b2fbd0 (gcl) [0x70000e766000]
1137
gdp_pdu_proc_resp: req@0x7fcddfbdc610:
1138
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1139
    postproc=0x0, sub_cb=0x0, udata=0x0
1140
    state=IDLE, stat=OK [200 = 0xc8]
1141
    act_ts=2017-04-19 00:16:11.981942000Z
1142
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
1143
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1144
	iomode = 3, refcnt = 7, reqs = 0x7fcdd9507460, nrecs = 0
1145
	flags = 0xa<INCACHE,INUSE>
1146
    cPDU@0x7fcddbb20490: 
1147
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
1148
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1149
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1150
	rid=6, olen=0, chan=0x0, seqno=0
1151
	flags=0
1152
	datum=0x0
1153
	total header=80
1154
    rPDU@0x7fcddfbe9860: 
1155
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
1156
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1157
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1158
	rid=6, olen=24, chan=0x7fcddfee0690, seqno=0
1159
	flags=0xa<HAS_RECNO,HAS_TS>
1160
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=1
1161
		ts=2017-04-19 00:16:12.008560000Z
1162
	sigmdalg=0x0, siglen=0, sig=0x0
1163
	total header=128
1164
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 7], req@0x7fcddfbdc610:
1165
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1166
    postproc=0x0, sub_cb=0x0, udata=0x0
1167
    state=IDLE, stat=OK [200 = 0xc8]
1168
    act_ts=2017-04-19 00:16:12.024079000Z
1169
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
1170
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1171
	iomode = 3, refcnt = 7, reqs = 0x7fcdd9507460, nrecs = 0
1172
	flags = 0xa<INCACHE,INUSE>
1173
    cPDU@0x7fcddbb20490: 
1174
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
1175
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1176
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1177
	rid=6, olen=0, chan=0x0, seqno=0
1178
	flags=0
1179
	datum=0x0
1180
	total header=80
1181
    rPDU@0x7fcddfbe9860: 
1182
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
1183
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1184
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1185
	rid=6, olen=24, chan=0x7fcddfee0690, seqno=0
1186
	flags=0xa<HAS_RECNO,HAS_TS>
1187
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=1
1188
		ts=2017-04-19 00:16:12.008560000Z
1189
	sigmdalg=0x0, siglen=0, sig=0x0
1190
	total header=128
1191

    
1192
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
1193
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 7]
1194
    OK [205 = 0xcd]
1195
    req@0x7fcddfbdc610:
1196
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1197
    postproc=0x0, sub_cb=0x0, udata=0x0
1198
    state=IDLE, stat=OK [200 = 0xc8]
1199
    act_ts=2017-04-19 00:16:12.024160000Z
1200
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
1201
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1202
	iomode = 3, refcnt = 7, reqs = 0x7fcdd9507460, nrecs = 1
1203
	flags = 0xa<INCACHE,INUSE>
1204
    cPDU@0x7fcddbb20490: 
1205
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
1206
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1207
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1208
	rid=6, olen=0, chan=0x0, seqno=0
1209
	flags=0
1210
	datum=0x0
1211
	total header=80
1212
    rPDU@0x7fcddfbe9860: 
1213
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
1214
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1215
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1216
	rid=6, olen=24, chan=0x7fcddfee0690, seqno=0
1217
	flags=0xa<HAS_RECNO,HAS_TS>
1218
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=1
1219
		ts=2017-04-19 00:16:12.008560000Z
1220
	sigmdalg=0x0, siglen=0, sig=0x0
1221
	total header=128
1222
acknak_from_estat: OK [205 = 0xcd] -> ACK_DATA_CONTENT
1223
gdp_pdu_proc_resp(ACK_DATA_CONTENT for CMD_SUBSCRIBE): OK [205 = 0xcd]
1224
req@0x7fcddfbdc610:
1225
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1226
    postproc=0x0, sub_cb=0x0, udata=0x0
1227
    state=IDLE, stat=OK [200 = 0xc8]
1228
    act_ts=2017-04-19 00:16:12.024160000Z
1229
    flags=0x1d7<ASYNCIO,DONE,CLT_SUBSCR,PERSIST,ALLOC_RID,ON_GCL_LIST,ON_CHAN_LIST>
1230
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1231
	iomode = 3, refcnt = 7, reqs = 0x7fcdd9507460, nrecs = 1
1232
	flags = 0xa<INCACHE,INUSE>
1233
    cPDU@0x7fcddbb20490: 
1234
	v=3, ttl=15, rsvd1=0, cmd=72=CMD_SUBSCRIBE
1235
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1236
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1237
	rid=6, olen=0, chan=0x0, seqno=0
1238
	flags=0
1239
	datum=0x0
1240
	total header=80
1241
    rPDU@0x7fcddfbe9860: 
1242
	v=3, ttl=15, rsvd1=0, cmd=133=ACK_DATA_CONTENT
1243
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1244
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1245
	rid=6, olen=24, chan=0x7fcddfee0690, seqno=0
1246
	flags=0xa<HAS_RECNO,HAS_TS>
1247
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=1
1248
		ts=2017-04-19 00:16:12.008560000Z
1249
	sigmdalg=0x0, siglen=0, sig=0x0
1250
	total header=128
1251
ep_thr_mutex_lock    gdp_event.c:72 0x158c81a20 (&FreeListMutex) [0x70000e766000]
1252
ep_thr_mutex_unlock  gdp_event.c:75 0x158c81a20 (&FreeListMutex) [0x70000e766000]
1253
_gdp_event_new => 0x7fcddb905b00
1254
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1255
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1256
gdp_datum_new => 0x7fcddffa9400
1257
_gdp_event_trigger: adding event 0x7fcddb905b00 (1) to active list
1258
ep_thr_mutex_lock    gdp_event.c:201 0x158c81a80 (&ActiveListMutex) [0x70000e766000]
1259
ep_thr_cond_broadcast gdp_event.c:203 0x158c81ae0 (&ActiveListSig) [0x70000e766000]
1260
ep_thr_mutex_unlock  gdp_event.c:204 0x158c81a80 (&ActiveListMutex) [0x70000e766000]
1261
_gdp_pdu_free(0x7fcddfbe9860)
1262
gdp_datum_free(0x7fcddb924820)
1263
  ... draining 1 bytes
1264
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
1265
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
1266
gdp_event_next: ep_thr_cond_wait => 0
1267
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1268
ep_thr_mutex_unlock  gdp_event.c:175 0x158c81a80 (&ActiveListMutex) [0x70000e6e0000]
1269
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1270
gdp_event_next => 0x7fcddb905b00
1271
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1272
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1273
_gdp_req_unlock: req @ 0x7fcddfbdc610
1274
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcddfbdc610 (&req->mutex) [0x70000e766000]
1275
gdp_pdu_proc_resp <<< done
1276
gdp_read_cb: fd 123, 88 bytes
1277
ep_thr_mutex_lock    gdp_pdu.c:780 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1278
ep_thr_mutex_unlock  gdp_pdu.c:789 0x158c81f60 (&PduFreeListMutex) [0x70000e766000]
1279
ep_thr_mutex_lock    gdp_datum.c:64 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1280
ep_thr_mutex_unlock  gdp_datum.c:69 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1281
gdp_datum_new => 0x7fcddb924820
1282
_gdp_pdu_new => 0x7fcddfbe9860
1283

    
1284
	>>>>>  _gdp_pdu_in  >>>>>
1285
_gdp_pdu_in: fixed pdu header:
1286
00000000 03 0f 00 81 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
1287
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
1288
00000020 41 73 6f 82 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b
1289
00000030 e7 55 90 84 72 97 22 9a 3b 1f 2f 05 10 b4 de 11
1290
00000040 68 82 24 42 00 00 00 00 00 00 02 02 00 00 00 00
1291
_gdp_pdu_in: read PDU header:
1292
00000000 03 0f 00 81 e9 f0 cb 52 38 c4 15 26 23 5e e6 a1
1293
00000010 a6 0d a3 a5 76 55 ce 7a 54 a4 d4 d3 99 d4 0c 5c
1294
00000020 41 73 6f 82 f5 16 bf d6 5f c2 46 a4 6d d3 dc 5b
1295
00000030 e7 55 90 84 72 97 22 9a 3b 1f 2f 05 10 b4 de 11
1296
00000040 68 82 24 42 00 00 00 00 00 00 02 02 00 00 00 00
1297
00000050 00 00 00 00 00 00 00 01
1298
_gdp_pdu_in: reading 0 data bytes (0 available)
1299
_gdp_pdu_in(ACK_DATA_CREATED) => OK
1300
PDU@0x7fcddfbe9860: 
1301
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1302
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1303
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1304
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1305
	flags=0x2<HAS_RECNO>
1306
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=0
1307
		ts=(none)
1308
	sigmdalg=0x0, siglen=0, sig=0x0
1309
	total header=96
1310

    
1311
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
1312
ep_thr_mutex_lock    ep_hash.c:169 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
1313
ep_thr_mutex_unlock  ep_hash.c:175 0x7fcde0506030 (&hp->mutex) [0x70000e766000]
1314
ep_thr_mutex_lock    gdp_gcl_cache.c:227 0x7fcde2b2fbd0 (gcl) [0x70000e766000]
1315
_gdp_gcl_touch(0x7fcde2b2fbd0)
1316
_gdp_gcl_incref(0x7fcde2b2fbd0): 8
1317
gdp_gcl_cache_get: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U =>
1318
	0x7fcde2b2fbd0 refcnt 8
1319
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
1320
gdp_pdu_proc_resp: searching gcl 0x7fcde2b2fbd0 for rid 0
1321
_gdp_req_find(gcl=0x7fcde2b2fbd0, rid=0)
1322
_gdp_req_lock: req @ 0x7fcdd9507460
1323
ep_thr_mutex_lock    gdp_req.c:383 0x7fcdd9507460 (&req->mutex) [0x70000e766000]
1324
_gdp_req_find(gcl=0x7fcde2b2fbd0, rid=0) => 0x7fcdd9507460, state WAITING
1325
... found req@0x7fcdd9507460:
1326
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1327
    postproc=0x0, sub_cb=0x0, udata=0x0
1328
    state=WAITING, stat=OK
1329
    act_ts=1970-01-01 00:00:00.000000000Z
1330
    flags=0x100<ON_CHAN_LIST>
1331
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1332
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1333
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
1334
    cPDU@0x7fcddff47cc0: 
1335
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1336
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1337
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1338
	rid=0, olen=0, chan=0x0, seqno=0
1339
	flags=0
1340
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=1
1341
		ts=(none)
1342
	sigmdalg=0x0, siglen=0, sig=0x0
1343
	total header=88
1344
ep_thr_mutex_unlock  gdp_main.c:410 0x7fcde2b2fbd0 (gcl) [0x70000e766000]
1345
gdp_pdu_proc_resp: req@0x7fcdd9507460:
1346
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1347
    postproc=0x0, sub_cb=0x0, udata=0x0
1348
    state=WAITING, stat=OK
1349
    act_ts=1970-01-01 00:00:00.000000000Z
1350
    flags=0x100<ON_CHAN_LIST>
1351
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1352
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1353
	flags = 0xa<INCACHE,INUSE>
1354
    cPDU@0x7fcddff47cc0: 
1355
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1356
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1357
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1358
	rid=0, olen=0, chan=0x0, seqno=0
1359
	flags=0
1360
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=1
1361
		ts=(none)
1362
	sigmdalg=0x0, siglen=0, sig=0x0
1363
	total header=88
1364
    rPDU@0x7fcddfbe9860: 
1365
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1366
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1367
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1368
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1369
	flags=0x2<HAS_RECNO>
1370
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=0
1371
		ts=(none)
1372
	sigmdalg=0x0, siglen=0, sig=0x0
1373
	total header=96
1374
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 8], req@0x7fcdd9507460:
1375
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1376
    postproc=0x0, sub_cb=0x0, udata=0x0
1377
    state=WAITING, stat=OK
1378
    act_ts=2017-04-19 00:16:12.025005000Z
1379
    flags=0x100<ON_CHAN_LIST>
1380
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1381
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1382
	flags = 0xa<INCACHE,INUSE>
1383
    cPDU@0x7fcddff47cc0: 
1384
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1385
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1386
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1387
	rid=0, olen=0, chan=0x0, seqno=0
1388
	flags=0
1389
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=1
1390
		ts=(none)
1391
	sigmdalg=0x0, siglen=0, sig=0x0
1392
	total header=88
1393
    rPDU@0x7fcddfbe9860: 
1394
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1395
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1396
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1397
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1398
	flags=0x2<HAS_RECNO>
1399
	datum=0x7fcddb924820, recno=1, dbuf=0x7fcde490d050, dlen=0
1400
		ts=(none)
1401
	sigmdalg=0x0, siglen=0, sig=0x0
1402
	total header=96
1403

    
1404
ack_success: received ACK_DATA_CREATED for CMD_APPEND
1405
ack_success: reusing old datum for req 0x7fcdd9507460
1406
   datum @ 0x7fcde2b77390: recno 1, len 1, no timestamp
1407
00000000 31
1408
         1 
1409
gdp_datum_free(0x7fcddb924820)
1410
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
1411
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddb924820 (&datum->mutex) [0x70000e766000]
1412
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1413
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70000e766000]
1414
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 8]
1415
    OK [201 = 0xc9]
1416
    req@0x7fcdd9507460:
1417
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1418
    postproc=0x0, sub_cb=0x0, udata=0x0
1419
    state=WAITING, stat=OK
1420
    act_ts=2017-04-19 00:16:12.025136000Z
1421
    flags=0x100<ON_CHAN_LIST>
1422
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1423
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1424
	flags = 0xa<INCACHE,INUSE>
1425
    cPDU@0x7fcddff47cc0: 
1426
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1427
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1428
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1429
	rid=0, olen=0, chan=0x0, seqno=0
1430
	flags=0
1431
	datum=0x0
1432
	total header=80
1433
    rPDU@0x7fcddfbe9860: 
1434
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1435
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1436
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1437
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1438
	flags=0x2<HAS_RECNO>
1439
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=0
1440
		ts=(none)
1441
	sigmdalg=0x0, siglen=0, sig=0x0
1442
	total header=96
1443
acknak_from_estat: OK [201 = 0xc9] -> ACK_DATA_CREATED
1444
gdp_pdu_proc_resp(ACK_DATA_CREATED for CMD_APPEND): OK [201 = 0xc9]
1445
req@0x7fcdd9507460:
1446
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1447
    postproc=0x0, sub_cb=0x0, udata=0x0
1448
    state=WAITING, stat=OK
1449
    act_ts=2017-04-19 00:16:12.025136000Z
1450
    flags=0x100<ON_CHAN_LIST>
1451
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1452
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1453
	flags = 0xa<INCACHE,INUSE>
1454
    cPDU@0x7fcddff47cc0: 
1455
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1456
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1457
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1458
	rid=0, olen=0, chan=0x0, seqno=0
1459
	flags=0
1460
	datum=0x0
1461
	total header=80
1462
    rPDU@0x7fcddfbe9860: 
1463
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1464
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1465
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1466
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1467
	flags=0x2<HAS_RECNO>
1468
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=0
1469
		ts=(none)
1470
	sigmdalg=0x0, siglen=0, sig=0x0
1471
	total header=96
1472
gdp_event_free(0x7fcddb905b00)
1473
gdp_pdu_proc_resp: signaling gdp_datum_free(0x7fcddffa9400)
1474
req@0x7fcdd9507460:
1475
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1476
    postproc=0x0, sub_cb=0x0, udata=0x0
1477
    state=WAITING, stat=OK [201 = 0xc9]
1478
    act_ts=2017-04-19 00:16:12.025136000Z
1479
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
1480
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1481
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1482
	flags = 0xa<INCACHE,INUSE>
1483
    cPDU@0x7fcddff47cc0: 
1484
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1485
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1486
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1487
	rid=0, olen=0, chan=0x0, seqno=0
1488
	flags=0
1489
	datum=0x0
1490
	total header=80
1491
    rPDU@0x7fcddfbe9860: 
1492
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1493
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1494
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1495
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1496
	flags=0x2<HAS_RECNO>
1497
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=0
1498
		ts=(none)
1499
	sigmdalg=0x0, siglen=0, sig=0x0
1500
	total header=96
1501
  ... draining 1 bytes
1502
ep_thr_cond_signal   gdp_main.c:497 0x7fcdd95074b0 (&req->cond) [0x70000e766000]
1503
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcddffa9400 (&datum->mutex) [0x70000e6e0000]
1504
ep_thr_yield         gdp_main.c:501 0x0 ((null)) [0x70000e766000]
1505
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcddffa9400 (&datum->mutex) [0x70000e6e0000]
1506
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x70000e6e0000]
1507
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x70000e6e0000]
1508
ep_thr_mutex_lock    gdp_event.c:104 0x158c81a20 (&FreeListMutex) [0x70000e6e0000]
1509
ep_thr_mutex_unlock  gdp_event.c:106 0x158c81a20 (&FreeListMutex) [0x70000e6e0000]
1510
_gdp_req_unlock: req @ 0x7fcdd9507460
1511
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcdd9507460 (&req->mutex) [0x70000e766000]
1512
gdp_pdu_proc_resp <<< done
1513
_gdp_req_unlock: req @ 0x7fcdd9507460
1514
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcdd9507460 (&req->mutex) [0x7000107fd000]
1515
ep_thr_mutex_lock    gdp_proto.c:153 0x7fcde2b2fbd0 (req->gcl) [0x7000107fd000]
1516
_gdp_req_lock: req @ 0x7fcdd9507460
1517
ep_thr_mutex_lock    gdp_req.c:383 0x7fcdd9507460 (&req->mutex) [0x7000107fd000]
1518
_gdp_invoke wait: got 0, done=1, state=2,
1519
    stat=OK [201 = 0xc9]
1520
_gdp_event_trigger_pending(0x7fcdd9507570): empty
1521
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_APPEND: OK [201 = 0xc9]
1522
  req@0x7fcdd9507460:
1523
    nextrec=0, numrecs=0, chan=0x7fcddfee0690
1524
    postproc=0x0, sub_cb=0x0, udata=0x0
1525
    state=ACTIVE, stat=OK [201 = 0xc9]
1526
    act_ts=2017-04-19 00:16:12.025136000Z
1527
    flags=0x103<ASYNCIO,DONE,ON_CHAN_LIST>
1528
    GCL@0x7fcde2b2fbd0: m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U
1529
	iomode = 3, refcnt = 8, reqs = 0x7fcddfbdc610, nrecs = 1
1530
	flags = 0xe<INCACHE,ISLOCKED,INUSE>
1531
    cPDU@0x7fcddff47cc0: 
1532
	v=3, ttl=15, rsvd1=0, cmd=71=CMD_APPEND
1533
	dst=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1534
	src=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1535
	rid=0, olen=0, chan=0x0, seqno=0
1536
	flags=0
1537
	datum=0x0
1538
	total header=80
1539
    rPDU@0x7fcddfbe9860: 
1540
	v=3, ttl=15, rsvd1=0, cmd=129=ACK_DATA_CREATED
1541
	dst=6fDLUjjEFSYjXuahpg2jpXZVznpUpNTTmdQMXEFzb4I
1542
	src=9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI
1543
	rid=0, olen=8, chan=0x7fcddfee0690, seqno=0
1544
	flags=0x2<HAS_RECNO>
1545
	datum=0x7fcde2b77390, recno=1, dbuf=0x7fcde4935e70, dlen=0
1546
		ts=(none)
1547
	sigmdalg=0x0, siglen=0, sig=0x0
1548
	total header=96
1549

    
1550
_gdp_req_free(0x7fcdd9507460)  state=1, gcl=0x7fcde2b2fbd0
1551
ep_thr_mutex_lock    gdp_req.c:272 0x7fcddfee0690 (&req->chan->mutex) [0x7000107fd000]
1552
ep_thr_mutex_unlock  gdp_req.c:275 0x7fcddfee0690 (&req->chan->mutex) [0x7000107fd000]
1553
_gdp_pdu_free(0x7fcddfbe9860)
1554
gdp_datum_free(0x7fcde2b77390)
1555
  ... draining 0 bytes
1556
ep_thr_mutex_trylock gdp_datum.c:117 0x7fcde2b77390 (&datum->mutex) [0x7000107fd000]
1557
ep_thr_mutex_unlock  gdp_datum.c:122 0x7fcde2b77390 (&datum->mutex) [0x7000107fd000]
1558
ep_thr_mutex_lock    gdp_datum.c:123 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
1559
ep_thr_mutex_unlock  gdp_datum.c:126 0x158c81ce0 (&DatumFreeListMutex) [0x7000107fd000]
1560
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
1561
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
1562
_gdp_pdu_free(0x7fcddff47cc0)
1563
ep_thr_mutex_lock    gdp_pdu.c:813 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
1564
ep_thr_mutex_unlock  gdp_pdu.c:815 0x158c81f60 (&PduFreeListMutex) [0x7000107fd000]
1565
ep_thr_mutex_lock    gdp_req.c:313 0x158c83070 (&ReqFreeListMutex) [0x7000107fd000]
1566
ep_thr_mutex_unlock  gdp_req.c:316 0x158c83070 (&ReqFreeListMutex) [0x7000107fd000]
1567
_gdp_req_unlock: req @ 0x7fcdd9507460
1568
ep_thr_mutex_unlock  gdp_req.c:404 0x7fcdd9507460 (&req->mutex) [0x7000107fd000]
1569
ep_thr_mutex_unlock  gdp_api.c:467 0x7fcde2b2fbd0 (gcl) [0x7000107fd000]
1570
<<< gdp_gcl_append: OK [201 = 0xc9]
1571
gdp_event_next: gcl 0x7fcde2b2fbd0
1572
ep_thr_mutex_lock    gdp_event.c:132 0x158c81a80 (&ActiveListMutex) [0x70000e6e0000]
1573
gdp_event_next: empty ActiveList; waiting
1574
ep_thr_cond_wait-cv  gdp_event.c:141 0x158c81ae0 (&ActiveListSig) [0x70000e6e0000]
1575
ep_thr_cond-wait-mtx gdp_event.c:141 0x158c81a80 (&ActiveListSig) [0x70000e6e0000]
1576
GDPHelper.subscribe(): about to call _notifyIncoming {recno=1, data=[B@5dc7f265, ts=EP_TIME_SPEC(auto-allocated@0x7fcdd95cdb50 (16 bytes)) {
1577
  long tv_sec@0=58f6ac4c
1578
  int tv_nsec@8=829d80
1579
  float tv_accuracy@c=0.0
1580
}}
1581
****** received: 1
1582
****** sent data: 1
1583
GDPLogRead.read(0): start
1584
GDPLogRead.read(0): About to call new GDP.GDP()
1585
GDPHelper.GDPHelper(ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023, 1, edu.berkeley.eecs.gdp-01.gdplogd): 
1586
GDPManager: Using configuration files in /Users/cxh/.ep_adm_params
1587
GDPManager: gdp settings:
1588
swarm.gdp.routers=gdp-03.eecs.berkeley.edu; gdp-02.eecs.berkeley.edu
1589
GDP_GCL.java: newGCL(org.terraswarm.gdp.GDP_NAME@69669e66, 1, org.terraswarm.gdp.GDP_NAME@2f2f8415)
1590
GDP_GCL.java: GDP_GCL(org.terraswarm.gdp.GDP_NAME@69669e66(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI), RO, org.terraswarm.gdp.GDP_NAME@2f2f8415(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
1591

    
1592
>>> gdp_gcl_open(9Ra_1l_CRqRt09xb51WQhHKXIpo7Hy8FELTeEWiCJEI)
1593
gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): using existing GCL @ 0x7fcde2b2fbd0
1594
<<< gdp_gcl_open(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
1595
GDPLogRead.read(0): recno was 0, sending nil
1596
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023
1597
Append data: 2
1598
GDPHelper.append(2)
1599
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1600

    
1601
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_APPEND (71), gcl@0x7fcde2b2fbd0
1602
	datum @ 0x7fcddffa9400: recno 2, len 1, no timestamp
1603
00000000 32
1604
         2 
1605
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_APPEND
1606
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1607

    
1608
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1609
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1610
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 10]
1611
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
1612
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 10]
1613
    OK [205 = 0xcd]
1614
_gdp_pdu_in(ACK_DATA_CREATED) => OK
1615

    
1616
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
1617
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
1618
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 11]
1619
ack_success: received ACK_DATA_CREATED for CMD_APPEND
1620
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 11]
1621
    OK [201 = 0xc9]
1622
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_APPEND: OK [201 = 0xc9]
1623
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@2740687c, ts=EP_TIME_SPEC(auto-allocated@0x7fcddfec8ac0 (16 bytes)) {
1624
  long tv_sec@0=58f6ac4c
1625
  int tv_nsec@8=375e7fe0
1626
  float tv_accuracy@c=0.0
1627
}}
1628
****** received: 2
1629
****** sent data: 2
1630
GDPLogRead.read(1): start
1631
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1632

    
1633
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_READ (70), gcl@0x7fcde2b2fbd0
1634
	datum @ 0x7fcddfee0da0: recno 1, len 0, no timestamp
1635
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_READ
1636
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1637

    
1638
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1639
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1640
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 12]
1641
ack_success: received ACK_DATA_CONTENT for CMD_READ
1642
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 12]
1643
    OK [205 = 0xcd]
1644
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_READ: OK [205 = 0xcd]
1645
GDPLogRead.read(1): sending 1
1646
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023
1647
Append data: 3
1648
GDPHelper.append(3)
1649
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1650

    
1651
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_APPEND (71), gcl@0x7fcde2b2fbd0
1652
	datum @ 0x7fcddb924820: recno 2, len 1, no timestamp
1653
00000000 33
1654
         3 
1655
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_APPEND
1656
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1657

    
1658
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1659
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1660
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 13]
1661
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
1662
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 13]
1663
    OK [205 = 0xcd]
1664
_gdp_pdu_in(ACK_DATA_CREATED) => OK
1665

    
1666
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
1667
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
1668
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 14]
1669
ack_success: received ACK_DATA_CREATED for CMD_APPEND
1670
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 14]
1671
    OK [201 = 0xc9]
1672
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_APPEND: OK [201 = 0xc9]
1673
GDPHelper.subscribe(): about to call _notifyIncoming {recno=2, data=[B@6ab2c21c, ts=EP_TIME_SPEC(auto-allocated@0x7fcddff74020 (16 bytes)) {
1674
  long tv_sec@0=58f6ac4d
1675
  int tv_nsec@8=378f6b50
1676
  float tv_accuracy@c=0.0
1677
}}
1678
****** received: 3
1679
****** sent data: 3
1680
GDPLogRead.read(2): start
1681
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1682

    
1683
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_READ (70), gcl@0x7fcde2b2fbd0
1684
	datum @ 0x7fcddffaede0: recno 2, len 0, no timestamp
1685
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_READ
1686
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1687

    
1688
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1689
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1690
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 15]
1691
ack_success: received ACK_DATA_CONTENT for CMD_READ
1692
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 15]
1693
    OK [205 = 0xcd]
1694
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_READ: OK [205 = 0xcd]
1695
GDPLogRead.read(2): sending 3
1696
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023
1697
Append data: 4
1698
GDPHelper.append(4)
1699
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1700

    
1701
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_APPEND (71), gcl@0x7fcde2b2fbd0
1702
	datum @ 0x7fcddffaf6e0: recno 3, len 1, no timestamp
1703
00000000 34
1704
         4 
1705
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_APPEND
1706
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1707

    
1708
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1709
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1710
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 16]
1711
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
1712
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 16]
1713
    OK [205 = 0xcd]
1714
_gdp_pdu_in(ACK_DATA_CREATED) => OK
1715

    
1716
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
1717
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
1718
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 17]
1719
ack_success: received ACK_DATA_CREATED for CMD_APPEND
1720
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 17]
1721
    OK [201 = 0xc9]
1722
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_APPEND: OK [201 = 0xc9]
1723
GDPHelper.subscribe(): about to call _notifyIncoming {recno=3, data=[B@d00c3d4, ts=EP_TIME_SPEC(auto-allocated@0x7fcdd948f4f0 (16 bytes)) {
1724
  long tv_sec@0=58f6ac4e
1725
  int tv_nsec@8=373d1530
1726
  float tv_accuracy@c=0.0
1727
}}
1728
****** received: 4
1729
****** sent data: 4
1730
GDPLogRead.read(3): start
1731
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1732

    
1733
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_READ (70), gcl@0x7fcde2b2fbd0
1734
	datum @ 0x7fcddfd7a430: recno 3, len 0, no timestamp
1735
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_READ
1736
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1737

    
1738
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1739
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1740
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 18]
1741
ack_success: received ACK_DATA_CONTENT for CMD_READ
1742
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 18]
1743
    OK [205 = 0xcd]
1744
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_READ: OK [205 = 0xcd]
1745
GDPLogRead.read(3): sending 4
1746
Append to log named: ptolemy.actor.lib.jjs.modules.gdp.test.auto.GDPLogAppendRead.0.3704672703275.-955030023
1747
Append data: 5
1748
GDPHelper.append(5)
1749
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1750

    
1751
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_APPEND (71), gcl@0x7fcde2b2fbd0
1752
	datum @ 0x7fcde2b005f0: recno 4, len 1, no timestamp
1753
00000000 35
1754
         5 
1755
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_APPEND
1756
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1757

    
1758
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1759
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1760
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 19]
1761
ack_success: received ACK_DATA_CONTENT for CMD_SUBSCRIBE
1762
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 19]
1763
    OK [205 = 0xcd]
1764
_gdp_pdu_in(ACK_DATA_CREATED) => OK
1765

    
1766
*** Processing ack/nak 129=ACK_DATA_CREATED from socket 123
1767
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CREATED) gcl 0x7fcde2b2fbd0
1768
_gdp_req_dispatch >>> ACK_DATA_CREATED (129) [gcl->refcnt 20]
1769
ack_success: received ACK_DATA_CREATED for CMD_APPEND
1770
_gdp_req_dispatch <<< ACK_DATA_CREATED [gcl->refcnt 20]
1771
    OK [201 = 0xc9]
1772
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_APPEND: OK [201 = 0xc9]
1773
GDPHelper.subscribe(): about to call _notifyIncoming {recno=4, data=[B@419947c5, ts=EP_TIME_SPEC(auto-allocated@0x7fcddfdb1ac0 (16 bytes)) {
1774
  long tv_sec@0=58f6ac4f
1775
  int tv_nsec@8=37922a70
1776
  float tv_accuracy@c=0.0
1777
}}
1778
****** received: 5
1779
****** sent data: 5
1780
GDPLogRead.read(4): start
1781
_gdp_req_new: allocated new pdu @ 0x7fcddff47cc0
1782

    
1783
>>> _gdp_invoke(req=0x7fcdd9507460 rid=0): CMD_READ (70), gcl@0x7fcde2b2fbd0
1784
	datum @ 0x7fcddfd70800: recno 4, len 0, no timestamp
1785
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_READ
1786
_gdp_pdu_in(ACK_DATA_CONTENT) => OK
1787

    
1788
*** Processing ack/nak 133=ACK_DATA_CONTENT from socket 123
1789
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_DATA_CONTENT) gcl 0x7fcde2b2fbd0
1790
_gdp_req_dispatch >>> ACK_DATA_CONTENT (133) [gcl->refcnt 21]
1791
ack_success: received ACK_DATA_CONTENT for CMD_READ
1792
_gdp_req_dispatch <<< ACK_DATA_CONTENT [gcl->refcnt 21]
1793
    OK [205 = 0xcd]
1794
<<< _gdp_invoke(0x7fcdd9507460 rid=0) CMD_READ: OK [205 = 0xcd]
1795
GDPLogRead.read(4): sending 5
1796

    
1797
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
1798
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
1799

    
1800
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
1801
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
1802

    
1803
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
1804
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
1805

    
1806
>>> gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U)
1807
<<< gdp_gcl_close(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U): OK
1808
7249 ms. Memory: 889344K Free: 793300K (89%)
1809

    
1810
>>> _gdp_invoke(req=0x7fcddfee1930 rid=3): CMD_SUBSCRIBE (72), gcl@0x7fcddfee2110
1811
	datum @ 0x7fcddfd70800: recno 3, len 4, no timestamp
1812
00000000 00 00 00 00
1813
         ?  ?  ?  ? 
1814
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_SUBSCRIBE
1815
_gdp_pdu_in(ACK_SUCCESS) => OK
1816

    
1817
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
1818
gdp_pdu_proc_resp(0x7fcddff47cc0 ACK_SUCCESS) gcl 0x7fcddfee2110
1819
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 17]
1820
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
1821
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 17]
1822
    OK [200 = 0xc8]
1823
<<< _gdp_invoke(0x7fcddfee1930 rid=3) CMD_SUBSCRIBE: OK [200 = 0xc8]
1824
subscr_resub(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U) ->
1825
	OK [200 = 0xc8]
1826

    
1827
>>> _gdp_invoke(req=0x7fcddfbdc610 rid=6): CMD_SUBSCRIBE (72), gcl@0x7fcde2b2fbd0
1828
	datum @ 0x7fcddfd70800: recno 5, len 4, no timestamp
1829
00000000 00 00 00 00
1830
         ?  ?  ?  ? 
1831
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_SUBSCRIBE
1832
_gdp_pdu_in(ACK_SUCCESS) => OK
1833

    
1834
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
1835
gdp_pdu_proc_resp(0x7fcde2b775d0 ACK_SUCCESS) gcl 0x7fcde2b2fbd0
1836
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 22]
1837
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
1838
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 22]
1839
    OK [200 = 0xc8]
1840
<<< _gdp_invoke(0x7fcddfbdc610 rid=6) CMD_SUBSCRIBE: OK [200 = 0xc8]
1841
subscr_resub(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U) ->
1842
	OK [200 = 0xc8]
1843

    
1844
>>> _gdp_invoke(req=0x7fcddfee1930 rid=3): CMD_SUBSCRIBE (72), gcl@0x7fcddfee2110
1845
	datum @ 0x7fcddfd70800: recno 3, len 4, no timestamp
1846
00000000 00 00 00 00
1847
         ?  ?  ?  ? 
1848
_gdp_pdu_out, fd = 123, basemd = 0x0: CMD_SUBSCRIBE
1849
_gdp_pdu_in(ACK_SUCCESS) => OK
1850

    
1851
*** Processing ack/nak 128=ACK_SUCCESS from socket 123
1852
gdp_pdu_proc_resp(0x7fcddfbe9860 ACK_SUCCESS) gcl 0x7fcddfee2110
1853
_gdp_req_dispatch >>> ACK_SUCCESS (128) [gcl->refcnt 18]
1854
ack_success: received ACK_SUCCESS for CMD_SUBSCRIBE
1855
_gdp_req_dispatch <<< ACK_SUCCESS [gcl->refcnt 18]
1856
    OK [200 = 0xc8]
1857
<<< _gdp_invoke(0x7fcddfee1930 rid=3) CMD_SUBSCRIBE: OK [200 = 0xc8]
1858
subscr_resub(m5FiAV65ufV8Oe3SinfrOZPcbzXtlNOG-lmD-KSsE1U) ->
1859
	OK [200 = 0xc8]